Home » RDBMS Server » Performance Tuning » A myth of TKPROF output in Oracle 10.1.0.4
| A myth of TKPROF output in Oracle 10.1.0.4 [message #161934] |
Tue, 07 March 2006 23:33  |
tphan_au
Messages: 3
Registered: March 2006
Location: Sydney
|
Junior Member |
|
|
Hi
Could some one please shred me some light on the following TKPROF's
output.
My questions:
1) Why a user SQL statements are shown as part of the recursive call
section, in stead of the non-recursive call section.
2) Why some SQL statements did not have a "wait event" section.
Eventhough a response times of that statement is very expensive.
3) Why a "FORALL" statement is too expensive.
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
TKPROF: Release 10.1.0.4.0 - Production on Tue Feb 21 10:43:26 2006
Copyright (c) 1982, 2004, Oracle. All rights reserved.
Trace file: srpidhpr_ora_9518.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for
update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
ALTER SESSION SET events '10046 trace name context forever, level 12'
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 0 0.00 0.00 0 0 0
0
Execute 1 0.00 0.00 0 0 0
0
Fetch 0 0.00 0.00 0 0 0
0
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 1 0.00 0.00 0 0 0
0
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 47 (IDH_APPLIC)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total
Waited
---------------------------------------- Waited ----------
------------
SQL*Net message to client 1 0.00
0.00
SQL*Net message from client 1 0.00
0.00
********************************************************************************
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 2 0.00 0.00 0 0 0
0
Execute 2 0.00 0.02 0 0 0
2
Fetch 0 0.00 0.00 0 0 0
0
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 4 0.00 0.02 0 0 0
2
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 47 (IDH_APPLIC)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total
Waited
---------------------------------------- Waited ----------
------------
SQL*Net message to client 2 0.00
0.00
SQL*Net message from client 2 0.00
0.00
********************************************************************************
BEGIN DBMS_OUTPUT.ENABLE(2000); END;
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 1 0.00 0.00 0 0 0
0
Execute 1 0.00 0.00 0 0 0
1
Fetch 0 0.00 0.00 0 0 0
0
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 2 0.00 0.00 0 0 0
1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 47 (IDH_APPLIC)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total
Waited
---------------------------------------- Waited ----------
------------
SQL*Net message to client 1 0.00
0.00
SQL*Net message from client 1 0.00
0.00
********************************************************************************
DECLARE
PROCEDURE WRITE_LOG(p_logMessage IN VARCHAR2
) as
BEGIN
BEGIN
dbms_output.PUT_LINE (p_logMessage);
EXCEPTION
WHEN OTHERS THEN
IF SQLCODE = -20000 THEN
dbms_output.DISABLE();
dbms_output.ENABLE(1000000);
dbms_output.PUT_LINE (p_logMessage);
END IF;
END;
END WRITE_LOG;
/* Load Promotional Item Table*/
PROCEDURE LOAD_PROMO_ITEM
IS
f_update INTEGER;
f_delete INTEGER;
ref_int_violated EXCEPTION;
PRAGMA EXCEPTION_INIT(ref_int_violated, -02291);
unique_constraint_violated EXCEPTION;
PRAGMA EXCEPTION_INIT(unique_constraint_violated, -00001);
null_value EXCEPTION;
PRAGMA EXCEPTION_INIT(null_value, -01400);
referenced_violated EXCEPTION;
PRAGMA EXCEPTION_INIT(referenced_violated, -02292);
TYPE dml_flag_tab IS TABLE OF
WW_MASTER.TEMP_PROM_ITEM.CHG_ACTN_IND%TYPE;
TYPE promotion_no_tab IS TABLE OF
WW_MASTER.TEMP_PROM_ITEM.ST_PROM_NO%TYPE;
TYPE group_code_tab IS TABLE OF
WW_MASTER.TEMP_PROM_ITEM.ST_ASRT_NO%TYPE;
TYPE item_no_tab IS TABLE OF WW_MASTER.TEMP_PROM_ITEM.REF_NO%TYPE;
TYPE promotional_sell_price_tab IS TABLE OF
WW_MASTER.TEMP_PROM_ITEM.PROM_SELL_PRC_AMT%TYPE;
TYPE standard_sell_price_tab IS TABLE OF
WW_MASTER.TEMP_PROM_ITEM.STD_SELL_PRC_AMT%TYPE;
TYPE new_item_ind_tab IS TABLE OF NUMBER(1);
dml_flag dml_flag_tab;
promotion_no promotion_no_tab;
group_code group_code_tab;
item_no item_no_tab;
promotional_sell_price promotional_sell_price_tab;
standard_sell_price standard_sell_price_tab;
new_item_ind new_item_ind_tab;
nat_prom_no promotion_no_tab;
CURSOR c_ins_cur
IS
select b.nat_prom_no,
b.st_prom_no,
case when (SELECT MAX( TRUNC(SYSDATE) - PROM_START_DATE )
FROM WW_OPERATIONAL.PROM_HIST
WHERE REF_NO = a.ref_no) > 70
then 0
else 1 end new_item_ind,
a.std_sell_prc_amt,
a.prom_sell_prc_amt,
a.ref_no
from temp_prom_item a, st_prom b
where a.st_prom_no = b.st_src_sys_id and
a.chg_actn_ind = 'I';
CURSOR c_upd_cur
IS
select c.nat_prom_no, b.st_prom_no,
a.std_sell_prc_amt,
a.prom_sell_prc_amt,
a.ref_no
from temp_prom_item a, st_prom b, nat_prom c, prom_item d
where a.st_prom_no = b.st_src_sys_id and
b.nat_prom_no = c.nat_prom_no and
b.st_prom_no = d.st_prom_no and
a.ref_no = d.ref_no and
( a.std_sell_prc_amt <> d.std_sell_prc_amt or
a.prom_sell_prc_amt <> d.prom_sell_prc_amt) and
a.chg_actn_ind = 'U';
CURSOR c_del_cur
IS
select b.st_prom_no,
a.ref_no
from temp_prom_item a, st_prom b
where a.st_prom_no = b.st_src_sys_id and
a.chg_actn_ind = 'D';
BEGIN
WRITE_LOG(' OPENED CURSOR FOR INSERTS AT '||TO_CHAR(SYSDATE,
'HH:MI:SS'));
OPEN c_ins_cur;
FETCH c_ins_cur BULK COLLECT INTO nat_prom_no, promotion_no,
new_item_ind, standard_sell_price,
promotional_sell_price, item_no;
CLOSE c_ins_cur;
WRITE_LOG(' FETCHED CURSOR FOR INSERTS AT '||TO_CHAR(SYSDATE,
'HH:MI:SS'));
WRITE_LOG(' START INSERTING INTO PROM_ITEM AT '||TO_CHAR(SYSDATE,
'HH:MI:SS'));
BEGIN
FORALL i IN 1 .. promotion_no.COUNT
INSERT INTO WW_OPERATIONAL.PROM_ITEM
( REF_NO, ST_PROM_NO, ASR_ITEM_IND, EDSD_ITEM_IND,
LOCK_STORE_UPDTE_IND, LOCK_EST_IND, NEW_ITEM_IND,
RVW_IND, EXCP_IND, PROM_SELL_PRC_AMT, STD_SELL_PRC_AMT)
VALUES
( item_no(i), promotion_no(i), 0, 0,
0, 0, new_item_ind(i),
0, 0, promotional_sell_price(i), standard_sell_price(i));
EXCEPTION
WHEN OTHERS THEN
WRITE_LOG('ERROR # 1: '||SQLCODE||SQLERRM);
RAISE_APPLICATION_ERROR( -20005, 'ERROR WHILE INSERTING INTO
PROM_ITEM. ');
END;
COMMIT;
BEGIN
FORALL i IN 1 .. promotion_no.COUNT
UPDATE WW_OPERATIONAL.ST_PROM
SET BUILD_QTY_CHG_FL = 1,
RVW_IND = 0,
EXCP_IND = CASE WHEN RVW_IND = 1 THEN 1 ELSE EXCP_IND END
WHERE ST_PROM_NO = promotion_no(i);
EXCEPTION
WHEN OTHERS THEN
WRITE_LOG('ERROR# 23: '||SQLCODE||SQLERRM);
RAISE_APPLICATION_ERROR( -20005, 'ERROR WHILE UPDATING
BUILD_QTY_CHG_FL. ');
END;
COMMIT;
BEGIN
FORALL i IN 1 .. promotion_no.COUNT
UPDATE WW_OPERATIONAL.PROM_ASRT
SET RVW_IND = 0,
EXCP_IND = CASE WHEN RVW_IND = 1 THEN 1 ELSE EXCP_IND END
WHERE ST_PROM_NO = promotion_no(i);
EXCEPTION
WHEN OTHERS THEN
WRITE_LOG('ERROR# 25: '||SQLCODE||SQLERRM);
RAISE_APPLICATION_ERROR( -20005, 'ERROR WHILE UPDATING PROM_ASRT
FOR EXCEPTION. ');
END;
COMMIT;
BEGIN
FORALL i IN 1 .. promotion_no.COUNT
UPDATE WW_OPERATIONAL.NAT_PROM
SET RVW_IND = 0,
EXCP_IND = CASE WHEN RVW_IND = 1 THEN 1 ELSE EXCP_IND END
WHERE NAT_PROM_NO = nat_prom_no(i);
EXCEPTION
WHEN OTHERS THEN
WRITE_LOG('ERROR# 27: '||SQLCODE||SQLERRM);
RAISE_APPLICATION_ERROR( -20005, 'ERROR WHILE UPDATING NAT_PROM FRO
EXCEPTION. ');
END;
COMMIT;
WRITE_LOG(' START INITIALIZING COLLECTION AT '||TO_CHAR(SYSDATE,
'HH:MI:SS'));
FOR i IN 1 .. promotion_no.COUNT
LOOP
promotion_no(i) := null;
item_no(i) := null;
promotional_sell_price(i) := null;
standard_sell_price(i) := null;
new_item_ind(i) := null;
nat_prom_no(i) := null;
END LOOP;
WRITE_LOG(' END INITIALIZING COLLECTION AT '||TO_CHAR(SYSDATE,
'HH:MI:SS'));
WRITE_LOG(' END INSERTING INTO PROM_ITEM AT '||TO_CHAR(SYSDATE,
'HH:MI:SS'));
BEGIN
SELECT 1
INTO f_update
FROM DUAL
WHERE EXISTS
( SELECT 1
FROM WW_MASTER.TEMP_PROM_ITEM
WHERE CHG_ACTN_IND = 'U');
EXCEPTION
WHEN NO_DATA_FOUND THEN
f_update := 0;
END;
IF f_update = 1
THEN
WRITE_LOG(' START FETCHING FOR UPDATES AT '||TO_CHAR(SYSDATE,
'HH:MI:SS'));
OPEN c_upd_cur;
FETCH c_upd_cur BULK COLLECT INTO nat_prom_no, promotion_no,
standard_sell_price,
promotional_sell_price,
item_no;
WRITE_LOG(' END FETCHING FOR UPDATES AT '||TO_CHAR(SYSDATE,
'HH:MI:SS'));
CLOSE c_upd_cur;
WRITE_LOG(' START UPDATING NAT_PROM WITH EXCEPTIONS AT
'||TO_CHAR(SYSDATE, 'HH:MI:SS'));
BEGIN
FORALL i IN 1 .. nat_prom_no.COUNT
UPDATE WW_OPERATIONAL.NAT_PROM
SET EXCP_IND = 1,
RVW_IND = 0,
LOCK_IND = 0
WHERE NAT_PROM_NO = nat_prom_no(i);
EXCEPTION
WHEN OTHERS THEN
ROLLBACK;
WRITE_LOG('ERROR # 2'||SQLCODE||SQLERRM);
RAISE_APPLICATION_ERROR( -20005, 'ERROR WHILE UPDATING NAT_PROM.');
END;
WRITE_LOG(' END UPDATING NAT_PROM WITH EXCEPTIONS AT
'||TO_CHAR(SYSDATE, 'HH:MI:SS'));
WRITE_LOG(' START UPDATING ST_PROM WITH EXCEPTIONS AT
'||TO_CHAR(SYSDATE, 'HH:MI:SS'));
BEGIN
FORALL i IN 1 .. nat_prom_no.COUNT
UPDATE WW_OPERATIONAL.ST_PROM
SET EXCP_IND = 1,
RVW_IND = 0
WHERE ST_PROM_NO = promotion_no(i);
EXCEPTION
WHEN OTHERS THEN
ROLLBACK;
WRITE_LOG('ERROR # 2'||SQLCODE||SQLERRM);
RAISE_APPLICATION_ERROR( -20005, 'ERROR WHILE UPDATING ST_PROM.');
END;
WRITE_LOG(' END UPDATING ST_PROM WITH EXCEPTIONS AT
'||TO_CHAR(SYSDATE, 'HH:MI:SS'));
WRITE_LOG(' START UPDATING PROM_ITEM WITH EXCEPTIONS AT
'||TO_CHAR(SYSDATE, 'HH:MI:SS'));
BEGIN
FORALL i IN 1 .. nat_prom_no.COUNT
UPDATE WW_OPERATIONAL.PROM_ITEM
SET EXCP_IND = 1,
RVW_IND = 0,
PROM_SELL_PRC_AMT = promotional_sell_price(i),
STD_SELL_PRC_AMT = standard_sell_price(i)
WHERE ST_PROM_NO = promotion_no(i) AND
REF_NO = item_no(i) ;
EXCEPTION
WHEN OTHERS THEN
ROLLBACK;
WRITE_LOG('ERROR # 2'||SQLCODE||SQLERRM);
RAISE_APPLICATION_ERROR( -20005, 'ERROR WHILE UPDATING
PROM_ITEM.');
END;
COMMIT;
WRITE_LOG(' END UPDATING PROM_ITEM WITH EXCEPTIONS AT
'||TO_CHAR(SYSDATE, 'HH:MI:SS'));
END IF;
WRITE_LOG(' START INITIALIZING COLLECTION FOR DELETES AT
'||TO_CHAR(SYSDATE, 'HH:MI:SS'));
FOR i IN 1 .. promotion_no.COUNT
LOOP
promotion_no(i) := null;
item_no(i) := null;
END LOOP;
WRITE_LOG(' END INITIALIZING COLLECTION FOR DELETES AT
'||TO_CHAR(SYSDATE, 'HH:MI:SS'));
BEGIN
SELECT 1
INTO f_delete
FROM DUAL
WHERE EXISTS
( SELECT 1
FROM WW_MASTER.TEMP_PROM_ITEM
WHERE CHG_ACTN_IND = 'D');
EXCEPTION
WHEN NO_DATA_FOUND THEN
f_delete := 0;
END;
IF f_delete = 1
THEN
WRITE_LOG(' START FETCHING FOR DELETES AT '||TO_CHAR(SYSDATE,
'HH:MI:SS'));
OPEN c_del_cur;
FETCH c_del_cur BULK COLLECT INTO promotion_no, item_no;
WRITE_LOG(' END FETCHING FOR DELETES AT '||TO_CHAR(SYSDATE,
'HH:MI:SS'));
WRITE_LOG(' START DELETING AT '||TO_CHAR(SYSDATE, 'HH:MI:SS'));
BEGIN
FORALL i IN 1 .. promotion_no.COUNT
DELETE FROM PROM_WKY_EST
WHERE ST_PROM_NO = promotion_no(i) AND
REF_NO = item_no(i);
EXCEPTION
WHEN OTHERS THEN
ROLLBACK;
WRITE_LOG(' ERROR # 5 '||SQLCODE||SQLERRM);
RAISE_APPLICATION_ERROR( -20005, 'ERROR WHILE DELETING FROM
PROM_WKY_EST.');
END;
BEGIN
FORALL i IN 1 .. promotion_no.COUNT
DELETE FROM PROM_DLY_EST
WHERE ST_PROM_NO = promotion_no(i) AND
REF_NO = item_no(i);
EXCEPTION
WHEN OTHERS THEN
ROLLBACK;
WRITE_LOG(' ERROR # 6 '||SQLCODE||SQLERRM);
RAISE_APPLICATION_ERROR( -20005, 'ERROR WHILE DELETING FROM
PROM_DLY_EST.');
END;
BEGIN
FORALL i IN 1 .. promotion_no.COUNT
DELETE FROM PROM_ITEM
WHERE REF_NO = item_no(i) AND
ST_PROM_NO = promotion_no(i);
EXCEPTION
WHEN OTHERS THEN
ROLLBACK;
WRITE_LOG(' ERROR # 7 '||SQLCODE||SQLERRM);
RAISE_APPLICATION_ERROR( -20005, 'ERROR WHILE DELETING FROM
PROM_ITEM.');
END;
COMMIT;
WRITE_LOG('END DELETING AT '||TO_CHAR(SYSDATE, 'HH:MI:SS'));
END IF;
END LOAD_PROMO_ITEM;
BEGIN
WRITE_LOG(' START TIME : '||TO_CHAR(SYSDATE, 'HH:MI:SS'));
LOAD_PROMO_ITEM;
WRITE_LOG(' END TIME : '||TO_CHAR(SYSDATE, 'HH:MI:SS'));
END;
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 1 0.10 0.09 0 0 0
0
Execute 1 2.31 2.33 0 0 4
1
Fetch 0 0.00 0.00 0 0 0
0
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 2 2.41 2.42 0 0 4
1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 47 (IDH_APPLIC)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total
Waited
---------------------------------------- Waited ----------
------------
SQL*Net message to client 1 0.00
0.00
SQL*Net message from client 1 0.00
0.00
********************************************************************************
SELECT B.NAT_PROM_NO, B.ST_PROM_NO, CASE WHEN (SELECT MAX(
TRUNC(SYSDATE) -
PROM_START_DATE )
FROM
WW_OPERATIONAL.PROM_HIST WHERE REF_NO = A.REF_NO) > 70 THEN 0 ELSE 1
END
NEW_ITEM_IND, A.STD_SELL_PRC_AMT, A.PROM_SELL_PRC_AMT, A.REF_NO FROM
TEMP_PROM_ITEM A, ST_PROM B WHERE A.ST_PROM_NO = B.ST_SRC_SYS_ID AND
A.CHG_ACTN_IND = 'I'
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 1 0.00 0.00 0 0 0
0
Execute 1 0.00 0.00 0 0 0
0
Fetch 1 769.48 1268.40 374933 84936470 0
327394
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 3 769.48 1268.41 374933 84936470 0
327394
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 47 (IDH_APPLIC) (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
327394 HASH JOIN (cr=13409 pr=0 pw=0 time=1722449 us)
188750 PARTITION RANGE ALL PARTITION: 1 6 (cr=8186 pr=0 pw=0
time=377596 us)
188750 TABLE ACCESS FULL ST_PROM PARTITION: 1 6 (cr=8186 pr=0 pw=0
time=188994 us)
327394 TABLE ACCESS FULL TEMP_PROM_ITEM (cr=5223 pr=0 pw=0 time=69
us)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
0 SORT (AGGREGATE)
0 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF
'PROM_HIST'
(TABLE)
0 INDEX MODE: ANALYZED (RANGE SCAN) OF 'IK16_PROM_HIST'
(INDEX)
327394 HASH JOIN
188750 PARTITION RANGE (ALL) PARTITION: START=1 STOP=6
188750 TABLE ACCESS MODE: ANALYZED (FULL) OF 'ST_PROM' (TABLE)
PARTITION: START=1 STOP=6
327394 TABLE ACCESS MODE: ANALYZED (FULL) OF 'TEMP_PROM_ITEM'
(TABLE)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total
Waited
---------------------------------------- Waited ----------
------------
db file sequential read 374933 0.03
129.32
********************************************************************************
INSERT INTO WW_OPERATIONAL.PROM_ITEM ( REF_NO, ST_PROM_NO,
ASR_ITEM_IND,
EDSD_ITEM_IND, LOCK_STORE_UPDTE_IND, LOCK_EST_IND, NEW_ITEM_IND,
RVW_IND,
EXCP_IND, PROM_SELL_PRC_AMT, STD_SELL_PRC_AMT)
VALUES
( :B1 , :B2 , 0, 0, 0, 0, :B3 , 0, 0, :B4 , :B5 )
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 1 0.00 0.00 0 0 0
0
Execute 1 20.91 26.08 789 27219 3214733
327394
Fetch 0 0.00 0.00 0 0 0
0
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 2 20.91 26.08 789 27219 3214733
327394
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 47 (IDH_APPLIC) (recursive depth: 1)
Rows Execution Plan
------- ---------------------------------------------------
0 INSERT STATEMENT MODE: ALL_ROWS
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total
Waited
---------------------------------------- Waited ----------
------------
db file sequential read 789 0.12
2.83
log file sync 14 0.07
0.63
********************************************************************************
select file#
from
file$ where ts#=:1
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 129 0.01 0.02 0 0 0
0
Execute 129 0.13 0.71 0 0 0
0
Fetch 930 0.01 0.01 0 1731 0
801
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 1188 0.15 0.75 0 1731 0
801
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
8 TABLE ACCESS BY INDEX ROWID FILE$ (cr=17 pr=0 pw=0 time=150
us)
8 INDEX RANGE SCAN I_FILE2 (cr=9 pr=0 pw=0 time=157 us)(object
id 42)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total
Waited
---------------------------------------- Waited ----------
------------
latch free 1 0.00
0.00
********************************************************************************
update tsq$ set
blocks=:3,maxblocks=:4,grantor#=:5,priv1=:6,priv2=:7,priv3=:8
where
ts#=:1 and user#=:2
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 15 0.00 0.00 0 0 0
0
Execute 15 0.07 0.52 0 52 15
15
Fetch 0 0.00 0.00 0 0 0
0
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 30 0.07 0.52 0 52 15
15
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
0 UPDATE (cr=4 pr=0 pw=0 time=512 us)
1 TABLE ACCESS CLUSTER TSQ$ (cr=4 pr=0 pw=0 time=233 us)
1 INDEX UNIQUE SCAN I_USER# (cr=1 pr=0 pw=0 time=33 us)(object
id 11)
********************************************************************************
update seg$ set
type#=:4,blocks=:5,extents=:6,minexts=:7,maxexts=:8,extsize=
:9,extpct=:10,user#=:11,iniexts=:12,lists=decode(:13, 65535, NULL,
:13),
groups=decode(:14, 65535, NULL, :14), cachehint=:15, hwmincr=:16,
spare1=
DECODE(:17,0,NULL,:17),scanhint=:18
where
ts#=:1 and file#=:2 and block#=:3
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 15 0.00 0.00 0 0 0
0
Execute 15 0.26 1.19 0 75 15
15
Fetch 0 0.00 0.00 0 0 0
0
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 30 0.26 1.19 0 75 15
15
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
0 UPDATE (cr=5 pr=0 pw=0 time=312 us)
1 TABLE ACCESS CLUSTER SEG$ (cr=5 pr=0 pw=0 time=151 us)
1 INDEX UNIQUE SCAN I_FILE#_BLOCK# (cr=2 pr=0 pw=0 time=28
us)(object id 9)
********************************************************************************
UPDATE WW_OPERATIONAL.ST_PROM SET BUILD_QTY_CHG_FL = 1, RVW_IND = 0,
EXCP_IND
= CASE WHEN RVW_IND = 1 THEN 1 ELSE EXCP_IND END
WHERE
ST_PROM_NO = :B1
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 1 0.00 0.00 0 0 0
0
Execute 1 360.19 1799.29 0 982245 677629
327394
Fetch 0 0.00 0.00 0 0 0
0
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 2 360.19 1799.29 0 982245 677629
327394
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 47 (IDH_APPLIC) (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
327394 UPDATE (cr=983038 pr=0 pw=0 time=27932704 us)
327394 TABLE ACCESS BY GLOBAL INDEX ROWID ST_PROM PARTITION: ROW
LOCATION ROW LOCATION (cr=982184 pr=0 pw=0 time=5239186 us)
327394 INDEX UNIQUE SCAN PK_ST_PROM (cr=654790 pr=0 pw=0
time=2540913 us)(object id 69189)
Rows Execution Plan
------- ---------------------------------------------------
0 UPDATE STATEMENT MODE: ALL_ROWS
327394 UPDATE OF 'ST_PROM'
327394 TABLE ACCESS MODE: ANALYZED (BY GLOBAL INDEX ROWID) OF
'ST_PROM' (TABLE) PARTITION:ROW LOCATION
327394 INDEX MODE: ANALYZED (UNIQUE SCAN) OF 'PK_ST_PROM' (INDEX
(UNIQUE))
********************************************************************************
UPDATE WW_OPERATIONAL.PROM_ASRT SET RVW_IND = 0, EXCP_IND = CASE WHEN
RVW_IND
= 1 THEN 1 ELSE EXCP_IND END
WHERE
ST_PROM_NO = :B1
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 1 0.00 0.00 0 0 0
0
Execute 1 398.22 2082.41 180 845142 388273
190214
Fetch 0 0.00 0.00 0 0 0
0
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 2 398.22 2082.41 180 845142 388273
190214
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 47 (IDH_APPLIC) (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
190214 UPDATE (cr=845142 pr=180 pw=0 time=34106085 us)
190214 TABLE ACCESS BY INDEX ROWID PROM_ASRT (cr=845002 pr=180 pw=0
time=12131193 us)
190214 INDEX UNIQUE SCAN PK_PROM_ASRT (cr=654788 pr=32 pw=0
time=7400800 us)(object id 49014)
Rows Execution Plan
------- ---------------------------------------------------
0 UPDATE STATEMENT MODE: ALL_ROWS
190214 UPDATE OF 'PROM_ASRT'
190214 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF
'PROM_ASRT'
(TABLE)
190214 INDEX MODE: ANALYZED (UNIQUE SCAN) OF 'PK_PROM_ASRT'
(INDEX (UNIQUE))
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total
Waited
---------------------------------------- Waited ----------
------------
log file switch completion 11 0.12
0.69
latch free 3 0.00
0.00
latch: cache buffers chains 1 0.00
0.00
db file sequential read 180 0.11
1.66
log file sync 6 0.48
1.22
********************************************************************************
UPDATE WW_OPERATIONAL.NAT_PROM SET RVW_IND = 0, EXCP_IND = CASE WHEN
RVW_IND =
1 THEN 1 ELSE EXCP_IND END
WHERE
NAT_PROM_NO = :B1
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 1 0.00 0.00 0 0 0
0
Execute 1 401.08 2086.53 2533 327452 336060
327394
Fetch 0 0.00 0.00 0 0 0
0
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 2 401.08 2086.53 2533 327452 336060
327394
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 47 (IDH_APPLIC) (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
327394 UPDATE (cr=327452 pr=2533 pw=0 time=39210456 us)
327394 INDEX UNIQUE SCAN PK_NAT_PROM (cr=327396 pr=28 pw=0
time=4660668 us)(object id 70804)
Rows Execution Plan
------- ---------------------------------------------------
0 UPDATE STATEMENT MODE: ALL_ROWS
327394 UPDATE OF 'NAT_PROM'
327394 INDEX MODE: ANALYZED (UNIQUE SCAN) OF 'PK_NAT_PROM' (INDEX
(UNIQUE))
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total
Waited
---------------------------------------- Waited ----------
------------
db file sequential read 2533 0.09
11.43
log file switch completion 14 0.17
0.99
latch: cache buffers chains 5 0.00
0.00
log file sync 6 0.72
1.50
latch: redo allocation 1 0.00
0.00
latch free 2 0.02
0.02
********************************************************************************
SELECT 1
FROM
DUAL WHERE EXISTS ( SELECT 1 FROM WW_MASTER.TEMP_PROM_ITEM WHERE
CHG_ACTN_IND = 'U')
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 1 0.00 0.00 0 0 0
0
Execute 1 0.74 6.98 5221 5223 0
0
Fetch 1 0.00 0.00 0 0 0
0
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 3 0.74 6.99 5221 5223 0
0
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 47 (IDH_APPLIC) (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 FILTER (cr=5223 pr=5221 pw=0 time=6986204 us)
0 FAST DUAL (cr=0 pr=0 pw=0 time=0 us)
0 TABLE ACCESS FULL TEMP_PROM_ITEM (cr=5223 pr=5221 pw=0
time=6986186 us)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
0 FILTER
0 FAST DUAL
0 TABLE ACCESS MODE: ANALYZED (FULL) OF 'TEMP_PROM_ITEM'
(TABLE)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total
Waited
---------------------------------------- Waited ----------
------------
db file sequential read 1 0.00
0.00
db file scattered read 332 0.13
6.09
********************************************************************************
SELECT 1
FROM
DUAL WHERE EXISTS ( SELECT 1 FROM WW_MASTER.TEMP_PROM_ITEM WHERE
CHG_ACTN_IND = 'D')
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 1 0.01 0.00 0 0 0
0
Execute 1 0.11 0.11 0 5223 0
0
Fetch 1 0.00 0.00 0 0 0
0
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 3 0.12 0.11 0 5223 0
0
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 47 (IDH_APPLIC) (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 FILTER (cr=5223 pr=0 pw=0 time=113807 us)
0 FAST DUAL (cr=0 pr=0 pw=0 time=0 us)
0 TABLE ACCESS FULL TEMP_PROM_ITEM (cr=5223 pr=0 pw=0
time=113787 us)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
0 FILTER
0 FAST DUAL
0 TABLE ACCESS MODE: ANALYZED (FULL) OF 'TEMP_PROM_ITEM'
(TABLE)
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 4 0.10 0.09 0 0 0
0
Execute 5 2.31 2.36 0 0 4
4
Fetch 0 0.00 0.00 0 0 0
0
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 9 2.41 2.45 0 0 4
4
Misses in library cache during parse: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total
Waited
---------------------------------------- Waited ----------
------------
SQL*Net message to client 5 0.00
0.00
SQL*Net message from client 5 0.00
0.01
SQL*Net more data from client 5 0.00
0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 166 0.02 0.04 0 0 0
0
Execute 166 1181.71 6003.85 8723 2192631 4616725
1172426
Fetch 933 769.49 1268.42 374933 84938201 0
328195
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 1265 1951.22 7272.32 383656 87130832 4616725
1500621
Misses in library cache during parse: 7
Misses in library cache during execute: 4
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total
Waited
---------------------------------------- Waited ----------
------------
db file sequential read 378436 0.12
145.26
log file sync 26 0.72
3.36
log file switch completion 25 0.17
1.68
latch free 6 0.02
0.02
latch: cache buffers chains 6 0.00
0.00
latch: redo allocation 1 0.00
0.00
db file scattered read 332 0.13
6.09
12 user SQL statements in session.
159 internal SQL statements in session.
171 SQL statements in session.
7 statements EXPLAINed in this session.
********************************************************************************
Trace file: srpidhpr_ora_9518.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
12 user SQL statements in trace file.
159 internal SQL statements in trace file.
171 SQL statements in trace file.
14 unique SQL statements in trace file.
7 SQL statements EXPLAINed using schema:
orametrics.plan_table
Schema was specified.
Existing table was used.
4312007 lines in trace file.
7275 elapsed seconds in trace file.
|
|
|
|
| Re: A myth of TKPROF output in Oracle 10.1.0.4 [message #161977 is a reply to message #161934] |
Wed, 08 March 2006 01:36  |
Frank
Messages: 7901
Registered: March 2000
|
Senior Member |
|
|
Your sql-statement is INSIDE a pl/sql-statement. Whence it's recursive depth is 1.
327000 rows in 1 forall update might be on the large side, causing a lot of overhead.
Next time, please, please use code-tags for better readability.
|
|
|
|
|
|
|
|
Goto Forum:
Current Time: Fri Apr 19 10:05:12 CDT 2024
|
] 
Blog
Search
Help
Members
Register
Login
Home
