RE: UPDATE statement - cpu and elapsed time almost the same
Date: Sun, 19 Nov 2017 03:02:55 +0000
Message-ID: <DM2PR11MB00903C9CB6ED31DC1C5E879EF42D0_at_DM2PR11MB0090.namprd11.prod.outlook.com>
Thanks Martin. I see the following information which only shows that the session was on the CPU. Thanks
SELECT
sample_id
, sample_time
, session_id
, session_serial#
, sql_id, session_state
, event
, p1
, p2
, p3
, sql_plan_operation
, current_block#
, current_row#
, in_parse
, in_hard_parse
, in_sql_execution
FROM dba_hist_active_sess_history
WHERE instance_number=3
AND session_id=1740
AND session_serial#=965
AND sql_id='bygjuxxcrd9y3';
SAMPLE_ID SAMPLE_TIME SID ser# SQL_ID SESSION EVENT P1 P2 P3 SQL_PLAN_OPE CURRENT_BLOCK# CURRENT_ROW# I I I ---------- ------------------------- ------ ------ ------------- ------- ---------- ---------- ---------- ---------- ------------ -------------- ------------ - - - 131663406 17-NOV-17 01.27.35.890 PM 1740 965 bygjuxxcrd9y3 ON CPU 2.8535E+10 2.7659E+10 3.2119E+16 UPDATE 0 0 N N Y 131663396 17-NOV-17 01.27.25.763 PM 1740 965 bygjuxxcrd9y3 ON CPU 2.8535E+10 2.7659E+10 3.2119E+16 UPDATE 0 0 N N Y 131663386 17-NOV-17 01.27.15.642 PM 1740 965 bygjuxxcrd9y3 ON CPU 2.8535E+10 2.7659E+10 3.2119E+16 UPDATE 0 0 N N Y 131663376 17-NOV-17 01.27.05.420 PM 1740 965 bygjuxxcrd9y3 ON CPU 2.8535E+10 2.7659E+10 3.2119E+16 UPDATE 0 0 N N Y 131663576 17-NOV-17 01.30.27.314 PM 1740 965 bygjuxxcrd9y3 ON CPU 3 2 0 UPDATE 0 0 N N Y 131663566 17-NOV-17 01.30.17.269 PM 1740 965 bygjuxxcrd9y3 ON CPU 3 2 0 UPDATE 0 0 N N Y 131663596 17-NOV-17 01.30.47.397 PM 1740 965 bygjuxxcrd9y3 ON CPU 3734728201 0 85 UPDATE 0 0 N N Y 131663586 17-NOV-17 01.30.37.349 PM 1740 965 bygjuxxcrd9y3 ON CPU 3734728201 2.7531E+12 91 UPDATE 0 0 N N Y
From: Martin Berger [mailto:martin.a.berger_at_gmail.com] Sent: Saturday, November 18, 2017 2:26 AM To: Hameed, Amir <Amir.Hameed_at_xerox.com> Cc: ORACLE-L <oracle-l_at_freelists.org> Subject: Re: UPDATE statement - cpu and elapsed time almost the same
Hi Amir,
(if you have diagnostic pack licensed) can you check in v$active_session_history (or DBA_ACTIVE_SESS_HISTORY) for session_state and event of this statement? Otherwise manual sampling of v$session.event might help as well. Or you can create a SQL-tracefile for this particular SQL, e.g. alter system set events 'sql_trace[sql: xxx] level=12'; A before/after information of v$sesstat will help also. If you have not seen it yet, Tanel Poders snapper<http://tech.e2sn.com/oracle-scripts-and-tools/session-snapper> can help you in collecting information (waits & session stats) about the running session.
With any of these information collected, you can go down the path and identify where the time is spent.
hth,
Martin
2017-11-18 2:50 GMT+01:00 Hameed, Amir <Amir.Hameed_at_xerox.com<mailto:Amir.Hameed_at_xerox.com>>:
Hi,
We traced an Oracle EBS Order Import form which was taking time to import orders. The trace file showed multiple UPDATE statements that were consuming time. What was common in all those statements was that their cpu time was almost the same as their elapsed time. I am pasting one of the statements, its statistics and explain plan. The explain plan seems to indicate that operation 1, which was executed 4 times, took most of the time. Was the time spent in this operation was due to the number of buffers processed which is memory operation and that is the reason cpu statistic was high? The columns being updated is indexed via a single-column index.
UPDATE OE_ORDER_LINES OEOPT SET ATO_LINE_ID = ( SELECT LINE_ID FROM
OE_ORDER_LINES OEATO
WHERE
OEOPT.TOP_MODEL_LINE_ID = OEATO.TOP_MODEL_LINE_ID AND OEATO.CONFIGURATION_ID
- (SELECT ATO_CONFIG_ITEM_ID FROM CZ_CONFIG_DETAILS_V WHERE CONFIG_HDR_ID = OEOPT.CONFIG_HEADER_ID AND CONFIG_REV_NBR = OEOPT.CONFIG_REV_NBR AND CONFIG_ITEM_ID = OEOPT.CONFIGURATION_ID) AND OEATO.OPEN_FLAG = 'Y' ) WHERE TOP_MODEL_LINE_ID = :B1 AND NOT (ITEM_TYPE_CODE = 'OPTION' AND ATO_LINE_ID = LINE_ID AND ATO_LINE_ID IS NOT NULL) AND NOT (ITEM_TYPE_CODE = 'INCLUDED' AND ATO_LINE_ID = LINE_ID AND ATO_LINE_ID IS NOT NULL) AND ITEM_TYPE_CODE <> 'CONFIG' AND (NVL(MODEL_REMNANT_FLAG, 'N') = 'N' OR LINE_CATEGORY_CODE = 'RETURN') AND ORDERED_QUANTITY > 0
Parse 1 0.00 0.00 0 0 0 0 Execute 4 174.74 174.86 0 646 261 30 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 5 174.74 174.86 0 646 261 30 ----------------------------------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers | ----------------------------------------------------------------------------------------------------------------------------------------------------- | 0 | UPDATE STATEMENT | | 0 | | | 12 (100)| | 0 |00:00:00.01 | 0 | | 1 | UPDATE | OE_ORDER_LINES_ALL | 4 | | | | | 0 |00:02:54.91 | 2335 | |* 2 | TABLE ACCESS BY INDEX ROWID | OE_ORDER_LINES_ALL | 4 | 1 | 454 | 5 (0)| 00:00:01 | 30 |00:00:00.01 | 60 | |* 3 | INDEX RANGE SCAN | OE_ORDER_LINES_N10 | 4 | 9 | | 1 (0)| 00:00:01 | 30 |00:00:00.01 | 8 | |* 4 | FILTER | | 30 | | | | | 26 |00:00:00.01 | 584 | |* 5 | TABLE ACCESS BY INDEX ROWID | OE_ORDER_LINES_ALL | 30 | 229 | 3664 | 6 (0)| 00:00:01 | 226 |00:00:00.01 | 382 | |* 6 | INDEX RANGE SCAN | OE_ORDER_LINES_N10 | 30 | 11 | | 1 (0)| 00:00:01 | 226 |00:00:00.01 | 50 | | 7 | NESTED LOOPS OUTER | | 30 | 1 | 310 | 0 (0)| | 30 |00:00:00.01 | 202 | | 8 | NESTED LOOPS | | 30 | 1 | 149 | 0 (0)| | 30 |00:00:00.01 | 172 | |* 9 | TABLE ACCESS BY INDEX ROWID| CZ_CONFIG_ITEMS | 30 | 1 | 108 | 0 (0)| | 30 |00:00:00.01 | 112 | |* 10 | INDEX RANGE SCAN | CZ_CONFIG_ITEMS_N1 | 30 | 1 | | 0 (0)| | 256 |00:00:00.01 | 50 | |* 11 | TABLE ACCESS BY INDEX ROWID| CZ_CONFIG_HDRS | 30 | 1 | 41 | 0 (0)| | 30 |00:00:00.01 | 60 | |* 12 | INDEX UNIQUE SCAN | CZ_CONFIG_HDRS_PK | 30 | 1 | | 0 (0)| | 30 |00:00:00.01 | 30 | |* 13 | INDEX UNIQUE SCAN | CZ_CONFIG_ATTRIBUTES_PK | 30 | 1 | 161 | 0 (0)| | 0 |00:00:00.01 | 30 | -----------------------------------------------------------------------------------------------------------------------------------------------------
Thank you,
Amir
--
Martin Berger +43 660 2978929<tel:+436602978929>
martin.a.berger_at_gmail.com<mailto:martin.a.berger_at_gmail.com> _at_martinberx<https://twitter.com/martinberx>
^∆x http://berxblog.blogspot.com
-- http://www.freelists.org/webpage/oracle-lReceived on Sun Nov 19 2017 - 04:02:55 CET