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>:

> 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
>
>
>
> call count cpu elapsed disk query
> current rows
>
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
>
> 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 <+436602978929>
martin.a.berger_at_gmail.com _at_martinberx <https://twitter.com/martinberx>
^∆x      http://berxblog.blogspot.com

--
http://www.freelists.org/webpage/oracle-l