Re: UPDATE statement - cpu and elapsed time almost the same

From: Stefan Koehler <contact_at_soocs.de>
Date: Sun, 19 Nov 2017 11:46:56 +0100 (CET)
Message-ID: <1829681872.185955.1511088416453_at_ox.hosteurope.de>


Hey Amir,
not quite sure what you have traced but the data between parsed extended SQL trace output and execution plan does not fit.

You have 4 EXEC OPI calls with 646/261 logical I/Os and 30 rows but your posted execution plan already has 2335 logical I/Os by 4 starts.

The problem is that Oracle does not provide any CPU break-down information in OPI call tracing or the execution plan - so basically you have to check session statistics (if there is any hint) or profile the shadow process.

I had a talk about this and you might find this interesting: http://www.soocs.de/public/talk/160616_DOAG_Regio_NUE_Identifying_Performance_Issues_Beyond_The_Oracle_Wait_Interface_PPT.pdf

Page 5 describes the general approach (you are basically at point 3 from now on) and the other slides include various tools for profiling.

Best Regards
Stefan Koehler

Independent Oracle performance consultant and researcher Website: http://www.soocs.de
Twitter: _at_OracleSK

>"Hameed, Amir" <Amir.Hameed_at_xerox.com> hat am 18. November 2017 um 02:50 geschrieben:

>
> 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 |
>
--
http://www.freelists.org/webpage/oracle-l
Received on Sun Nov 19 2017 - 11:46:56 CET

Original text of this message