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