| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
Home -> Community -> Usenet -> c.d.o.server -> Help interpreting TKPROF output
Hi everyone,
I'm trying to figure out what might have slowed down considerably a specific query these past days. I asked for a TKPROF output for only this statement, and the relevant sections of it are displayed at the bottom of this message. First some background: They use Oracle 8.1.7, and RBO (this is enforced by the vendor, Siebel, who digests "new" database features like cost-based optimizing VERY slowly). I'm told that this query used to run in about 20 seconds, and it takes now 11 minutes!! I asked if anything to the SQL generated by Siebel got modified, and I was told no. (for you Sybrand:)I went through the Performance Tuning manual, in order to get some tips on how to interpret TKPROF output, but I'm afraid that's not enough. I don't see anything wrong with the execution plan. Here is the TKPROF output:
TKPROF: Release 8.1.7.3.0 - Production on Tue Nov 4 15:47:30 2003
(c) Copyright 2000 Oracle Corporation. All rights reserved.
Trace file: ora_2998_orpo.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 ********************************************************************************
select
T1.LAST_UPD_BY, T1.ROW_ID, T1.CONFLICT_ID, T1.CREATED_BY, T1.CREATED, T1.LAST_UPD, T1.MODIFICATION_NUM,
T9.BL_CLASS_CD, T1.TODO_CD, T1.OWNER_PER_ID, T1.PREV_ACT_ID, T1.COMMENTS_LONG, T1.OWNER_LOGIN, T1.APPT_START_DT, T4.PLAN_START_DT, T1.OWNER_OU_ID, T1.PROJ_ITEM_ID, T1.TEMPLATE_FLG,
T3.CREATED, T5.ACT_APPT_START_DT, T5.ROW_STATUS, T4.ACTL_END_DT,
T22.PAR_ROW_ID, T1.APPT_ALARM_TM_MIN, T22.ROW_ID,
T9.NAME, T1.ASGN_MANL_FLG, T4.PLAN_END_DT, T18.CREATED_BY, T1.X_GM_VEH_MOD_YR, T3.CURR_STG_ID, T21.PAR_ROW_ID,
T1.PCT_COMPLETE, T1.EVT_PRIORITY_CD, T1.CAL_DISP_FLG, T1.PROJ_ID,
T23.SUB_TYPE_CD, T22.CREATED, T19.LAST_NAME,
T1.APPT_REPT_TYPE, T1.APPT_REPT_FLG, T1.TARGET_PER_ID,
T3.SRC_TYPE_CD, T1.APPT_END_DT, T1.DONE_FLG, T1.PYMNT_FLG,
T1.CREATOR_LOGIN, T5.ROW_ID, T1.CAL_TYPE_CD, T1.OPTY_ID, T3.SRC_TYPE_CD, T1.X_GM_AUTOCREATED_FLG,
T1.PERFRM_BY_OU_ID, T5.ACT_TEMPLATE_FLG, T1.APPT_REPT_END_DT, T1.COMMENTS, T1.X_GM_ACT_OUTCOME, T20.LAST_NAME, T24.LAST_NAME, T19.HOME_PH_NUM, T22.MODIFICATION_NUM,
T3.X_GM_PURCHASED_MAKE, T1.ALARM_FLAG, T1.PR_CONTAINER_ID, T1.ACCNT_SRC_ID, T1.TODO_PLAN_END_DT, T18.CREATED, T11.ATTRIB_31, T18.LAST_UPD,
T2.NAME, T3.LEAD_QUALITY_CD, T1.ACT_TMPL_ID,
T1.TODO_AFTER_DT, T5.ACT_APPT_REPT_FLG, T2.ROW_ID, T1.ASGN_SYS_FLG, T1.ASSET_ID, T5.EMP_ID, T1.AGREEMENT_ID, T1.PAR_EVT_ID, T16.ROW_ID, T1.X_GM_VEH_MODEL, T1.COST_CURCY_CD, T2.LOC, T1.PERFRM_BY_PER_ID,
T5.ACT_APPT_RPTEND_DT, T3.X_GM_OPTY_TYPE, T5.ACT_TODO_PLNSTRTDT, T18.ROW_ID,
T18.LAST_UPD_BY, T21.ROW_ID, T22.CREATED_BY, T1.X_GM_SUB_TYPE, T1.APPT_REPT_REPL_CD, T7.FST_NAME, T1.PR_ORDER_ID, T1.TODO_PLAN_START_DT, T1.NAME,
T1.APPT_DURATION_MIN, T3.X_GM_PURCHASED_MODEL, T9.BL_CURCY_CD,
T1.TODO_ACTL_END_DT, T8.NAME, T2.BASE_CURCY_CD, T1.X_GM_VEH_EXT_COL, T21.CREATED,
SIEBEL.S_EVT_ACT T1, SIEBEL.S_ORG_EXT T2, SIEBEL.S_OPTY T3, SIEBEL.S_PROJITEM T4, SIEBEL.S_ACT_EMP T5, SIEBEL.S_PARTY_RPT_REL T6, SIEBEL.S_CONTACT T7, SIEBEL.S_STG T8, SIEBEL.S_PROJ T9, SIEBEL.S_EVT_ACT T10, SIEBEL.S_OPTY_X T11, SIEBEL.S_PARTY T12, SIEBEL.S_CONTACT T13, SIEBEL.S_CONTACT T14, SIEBEL.S_PROD_INT T15, SIEBEL.S_ACT_PROD_APPL T16, SIEBEL.S_PROD_INT T17, SIEBEL.S_SRV_ACT T18, SIEBEL.S_CONTACT T19, SIEBEL.S_CONTACT T20, SIEBEL.S_EVT_ACT_SS T21, SIEBEL.S_EVT_MAIL T22, SIEBEL.S_ASSET T23, SIEBEL.S_CONTACT T24, SIEBEL.S_LANG T25
T3.CURR_STG_ID = T8.ROW_ID (+) AND T1.OWNER_PER_ID = T13.PAR_ROW_ID (+) AND T1.TARGET_PER_ID = T20.PAR_ROW_ID (+) AND T1.TARGET_PER_ID = T20.PAR_ROW_ID (+) AND T1.ASSET_ID = T23.ROW_ID (+) AND T1.TARGET_PER_ID = T14.PAR_ROW_ID (+) AND T1.OPTY_ID = T3.ROW_ID (+) AND T1.TARGET_OU_ID = T2.PAR_ROW_ID (+) AND T1.PROJ_ID = T9.ROW_ID (+) AND T1.PROJ_ITEM_ID = T4.ROW_ID (+) AND T1.TEMPLATE_ID = T10.ROW_ID (+) AND T1.OPTY_ID = T11.PAR_ROW_ID (+) AND T1.PERFRM_BY_PER_ID = T7.PAR_ROW_ID (+) AND T1.TARGET_PER_ID = T19.ROW_ID (+) AND
T1.ROW_ID = T22.PAR_ROW_ID (+) AND T1.ROW_ID = T21.PAR_ROW_ID (+) AND T1.ROW_ID = T18.PAR_ROW_ID (+) AND T1.OWNER_PER_ID = T5.EMP_ID (+) AND T1.ROW_ID = T5.ACTIVITY_ID (+) AND T5.EMP_ID = T12.ROW_ID (+) AND T5.EMP_ID = T24.PAR_ROW_ID (+) AND T1.PR_PRDINT_ID = T16.ROW_ID (+) AND
T1.OPTY_ID IN ( SELECT SQ1_T1.OPTY_ID
FROM SIEBEL.S_OPTY_POSTN SQ1_T1, SIEBEL.S_PARTY
SQ1_T2, SIEBEL.S_CONTACT SQ1_T3, SIEBEL.S_POSTN SQ1_T4
WHERE
(SQ1_T4.PR_EMP_ID = SQ1_T3.PAR_ROW_ID (+) AND
SQ1_T2.ROW_ID = SQ1_T4.PAR_ROW_ID
AND
(SQ1_T3.ROW_ID = '1-29WRP')))) AND (T6.PARTY_ID = '1-2J-5235') AND (T1.PRIV_FLG = 'N' OR T1.PRIV_FLG IS NULL OR T1.OWNER_PER_ID =
call count cpu elapsed disk query current
rows
Parse 1 0.34 0.53 0 0 0
0
Execute 1 0.00 0.00 0 0 0
0
Fetch 1 366.73 659.36 140803 28921647 15
0
total 3 367.07 659.89 140803 28921647 15
0
Misses in library cache during parse: 1
Optimizer goal: RULE
Parsing user id: 5 (SYSTEM)
Rows Row Source Operation
------- ---------------------------------------------------
0 FILTER
1 FILTER
1745637 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 NESTED LOOPS OUTER
873290 TABLE ACCESS FULL S_EVT_ACT
770325 TABLE ACCESS BY INDEX ROWID S_ASSET
1643614 INDEX UNIQUE SCAN (object id
163988)
869748 TABLE ACCESS BY INDEX ROWID
S_CONTACT
1743037 INDEX UNIQUE SCAN (object id
165128)
869748 TABLE ACCESS BY INDEX ROWID S_CONTACT
1743037 INDEX UNIQUE SCAN (object id 165122)
2395 TABLE ACCESS BY INDEX ROWID S_LANG
875684 INDEX UNIQUE SCAN (object id 168360)
770256 TABLE ACCESS BY INDEX ROWID S_PROD_INT
1643545 INDEX UNIQUE SCAN (object id 170462)
0 TABLE ACCESS BY INDEX ROWID
S_ACT_PROD_APPL
873289 INDEX UNIQUE SCAN (object id 163543)
0 TABLE ACCESS BY INDEX ROWID S_PROD_INT
873289 INDEX UNIQUE SCAN (object id 170462)
869748 TABLE ACCESS BY INDEX ROWID S_CONTACT
1743037 INDEX UNIQUE SCAN (object id 165128)
872359 TABLE ACCESS BY INDEX ROWID S_CONTACT
1745648 INDEX UNIQUE SCAN (object id 165128)
0 TABLE ACCESS BY INDEX ROWID S_EVT_ACT
873289 INDEX UNIQUE SCAN (object id 166898)
0 TABLE ACCESS BY INDEX ROWID S_PROJ
873289 INDEX UNIQUE SCAN (object id 170716)
513307 TABLE ACCESS BY INDEX ROWID S_CONTACT
1386596 INDEX UNIQUE SCAN (object id 165128)
0 TABLE ACCESS BY INDEX ROWID S_PROJITEM
873289 INDEX UNIQUE SCAN (object id 170731)
839750 TABLE ACCESS BY INDEX ROWID S_OPTY
1713039 INDEX UNIQUE SCAN (object id 168882)
39271 TABLE ACCESS BY INDEX ROWID S_STG
912560 INDEX UNIQUE SCAN (object id 172136)
5 TABLE ACCESS BY INDEX ROWID S_ORG_EXT
873294 INDEX UNIQUE SCAN (object id 169420)
871010 TABLE ACCESS BY INDEX ROWID S_ACT_EMP
1747897 INDEX RANGE SCAN (object id 174811)
870996 TABLE ACCESS BY INDEX ROWID S_CONTACT
1744285 INDEX UNIQUE SCAN (object id 165128)
870996 INDEX UNIQUE SCAN (object id 169766)
170 TABLE ACCESS BY INDEX ROWID S_EVT_MAIL
873459 INDEX RANGE SCAN (object id 167006)
0 TABLE ACCESS BY INDEX ROWID S_EVT_ACT_SS
873289 INDEX RANGE SCAN (object id 166977)
31 TABLE ACCESS BY INDEX ROWID S_SRV_ACT
873320 INDEX RANGE SCAN (object id 171966)
809443 TABLE ACCESS BY INDEX ROWID S_OPTY_X
1682732 INDEX RANGE SCAN (object id 169153)
1744696 INDEX RANGE SCAN (object id 169797)
0 FILTER
0 NESTED LOOPS OUTER
0 NESTED LOOPS
0 NESTED LOOPS
0 INDEX RANGE SCAN (object id 169071)
0 INDEX UNIQUE SCAN (object id 169766)
0 TABLE ACCESS BY INDEX ROWID S_POSTN
0 INDEX UNIQUE SCAN (object id 170114)
0 TABLE ACCESS BY INDEX ROWID S_CONTACT
0 INDEX UNIQUE SCAN (object id 165128)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: RULE
0 FILTER
1 FILTER
1745637 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 NESTED LOOPS (OUTER)
873290 TABLE ACCESS (FULL) OF 'S_EVT_ACT'
770325 TABLE ACCESS (BY INDEX ROWID) OF
'S_ASSET'
1643614 INDEX (UNIQUE SCAN) OF
'S_ASSET_P1' (UNIQUE)
869748 TABLE ACCESS (BY INDEX ROWID) OF
'S_CONTACT'
1743037 INDEX (UNIQUE SCAN) OF
'S_CONTACT_U2' (UNIQUE)
869748 TABLE ACCESS (BY INDEX ROWID) OF
'S_CONTACT'
1743037 INDEX (UNIQUE SCAN) OF
'S_CONTACT_P1' (UNIQUE)
2395 TABLE ACCESS (BY INDEX ROWID) OF
'S_LANG'
875684 INDEX (UNIQUE SCAN) OF 'S_LANG_P1'
(UNIQUE)
770256 TABLE ACCESS (BY INDEX ROWID) OF
'S_PROD_INT'
1643545 INDEX (UNIQUE SCAN) OF
'S_PROD_INT_P1' (UNIQUE)
0 TABLE ACCESS (BY INDEX ROWID) OF
'S_ACT_PROD_APPL'
873289 INDEX (UNIQUE SCAN) OF
'S_ACT_PROD_APPL_P1' (UNIQUE)
0 TABLE ACCESS (BY INDEX ROWID) OF
'S_PROD_INT'
873289 INDEX (UNIQUE SCAN) OF 'S_PROD_INT_P1'
(UNIQUE)
869748 TABLE ACCESS (BY INDEX ROWID) OF
'S_CONTACT'
1743037 INDEX (UNIQUE SCAN) OF 'S_CONTACT_U2'
(UNIQUE)
872359 TABLE ACCESS (BY INDEX ROWID) OF
'S_CONTACT'
1745648 INDEX (UNIQUE SCAN) OF 'S_CONTACT_U2'
(UNIQUE)
0 TABLE ACCESS (BY INDEX ROWID) OF
'S_EVT_ACT'
873289 INDEX (UNIQUE SCAN) OF 'S_EVT_ACT_P1'
(UNIQUE)
0 TABLE ACCESS (BY INDEX ROWID) OF 'S_PROJ'
873289 INDEX (UNIQUE SCAN) OF 'S_PROJ_P1' (UNIQUE)
513307 TABLE ACCESS (BY INDEX ROWID) OF 'S_CONTACT'
1386596 INDEX (UNIQUE SCAN) OF 'S_CONTACT_U2'
(UNIQUE)
0 TABLE ACCESS (BY INDEX ROWID) OF 'S_PROJITEM'
873289 INDEX (UNIQUE SCAN) OF 'S_PROJITEM_P1'
(UNIQUE)
839750 TABLE ACCESS (BY INDEX ROWID) OF 'S_OPTY'
1713039 INDEX (UNIQUE SCAN) OF 'S_OPTY_P1' (UNIQUE)
39271 TABLE ACCESS (BY INDEX ROWID) OF 'S_STG'
912560 INDEX (UNIQUE SCAN) OF 'S_STG_P1' (UNIQUE)
5 TABLE ACCESS (BY INDEX ROWID) OF 'S_ORG_EXT'
873294 INDEX (UNIQUE SCAN) OF 'S_ORG_EXT_U3' (UNIQUE)
871010 TABLE ACCESS (BY INDEX ROWID) OF 'S_ACT_EMP'
1747897 INDEX (RANGE SCAN) OF 'S_ACT_EMP_F1' (NON-UNIQUE)
870996 TABLE ACCESS (BY INDEX ROWID) OF 'S_CONTACT'
1744285 INDEX (UNIQUE SCAN) OF 'S_CONTACT_U2' (UNIQUE)
870996 INDEX (UNIQUE SCAN) OF 'S_PARTY_P1' (UNIQUE)
170 TABLE ACCESS (BY INDEX ROWID) OF 'S_EVT_MAIL'
873459 INDEX (RANGE SCAN) OF 'S_EVT_MAIL_U1' (UNIQUE)
0 TABLE ACCESS (BY INDEX ROWID) OF 'S_EVT_ACT_SS'
873289 INDEX (RANGE SCAN) OF 'S_EVT_ACT_SS_U1' (UNIQUE)
31 TABLE ACCESS (BY INDEX ROWID) OF 'S_SRV_ACT'
873320 INDEX (RANGE SCAN) OF 'S_SRV_ACT_U1' (UNIQUE)
809443 TABLE ACCESS (BY INDEX ROWID) OF 'S_OPTY_X'
1682732 INDEX (RANGE SCAN) OF 'S_OPTY_X_U1' (UNIQUE)
1744696 INDEX (RANGE SCAN) OF 'S_PARTY_RPT_REL_U2' (UNIQUE)
0 FILTER
0 NESTED LOOPS (OUTER)
0 NESTED LOOPS
0 NESTED LOOPS
0 INDEX (RANGE SCAN) OF 'S_OPTY_POSTN_U1' (UNIQUE)
0 INDEX (UNIQUE SCAN) OF 'S_PARTY_P1' (UNIQUE)
0 TABLE ACCESS (BY INDEX ROWID) OF 'S_POSTN'
0 INDEX (UNIQUE SCAN) OF 'S_POSTN_U2' (UNIQUE)
0 TABLE ACCESS (BY INDEX ROWID) OF 'S_CONTACT'
0 INDEX (UNIQUE SCAN) OF 'S_CONTACT_U2' (UNIQUE)
********************************************************************************
Trace file: ora_2998_orpo.trc
Trace file compatibility: 8.00.04
Sort options: default
1 session in tracefile.
5 user SQL statements in trace file.
70 internal SQL statements in trace file.
75 SQL statements in trace file.
14 unique SQL statements in trace file.
1 SQL statements EXPLAINed using schema:
SYSTEM.prof$plan_table
Default table was used.
Table was created.
Table was dropped.
Anyone has an idea as to what might be wrong? Or is there any other tool (besides TKPROF) that they might use to better tune this statement?
Daniel Received on Fri Nov 07 2003 - 14:54:25 CST
![]() |
![]() |