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_IDAND
(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