Using Oracle Trace Event 10046 to Troubleshoot Clarity Performance Issues

This entry is a brief discription of using the Oracle trace event 10046 to identify exactly what a query is doing. SQL Trace at the database level is the most in depth analysis that can be performed on a query to identify exactly what is happening at runtime.

Oracle documentation on SQL Trace can be found here ORACLE TRACE DOCUMENTATION

To perform this tracing you need access to the Oracle database in order to recover the trace file and run TKPROF on it. It's possible to put the trace fiule on another machine and then TKPROF it but you will not be able to use certain options, like EXPLAIN PLAN.Here's a quick outline of the issue and then steps to enable tracing.

Login to the machine, for this example I assume you are on the actual database server, it's a Linux box and you are using SQLPLUS. 

sqlplus / as sysdba 
ALTER SESSION SET EVENTS '10046 trace name context forever, level 4'; ALTER SESSION SET CURRENT_SCHEMA=YOUR_CLARITY_SCHEMA; -- Example trace select * from (select row_number() over ( order by key asc) row_num, count(*) over () num_rows, q.* from ( SELECT bms.bms_date_key key, bms.bms_date bms_date, sum(bms.scheduled) scheduled, sum(bms.actual) actual, bms.obs_id obs FROM ( select to_char(bms_sched_ms_date , 'YYYY/MM') as BMS_date_key, to_char(bms_sched_ms_date , 'Mon YYYY') as BMS_date, sum(bms_plan_billed) as scheduled, 0 as actual, 'scheduled' as amount_type, flat.branch_unit_id obs_id from odf_ca_eri_prj_bill_mlstone bms , odf_ca_project odf , inv_investments inv , odf_ca_project parent_odf , prj_obs_associations assoc , prj_obs_units_flat flat , prj_obs_units unt where bms_sched_ms_date is not null and bms.bms_actual_date is null and bms.odf_parent_id = odf.id and odf.eri_prj_level != 1 and odf.id = inv.id and parent_odf.eri_prj_level = 1 and odf.eri_proj_number = parent_odf.eri_proj_number and inv.id = assoc.record_id (+) and assoc.table_name(+) = 'SRM_PROJECTS' and assoc.unit_id = flat.unit_id(+) and unt.type_id (+) = 5000034 and assoc.unit_id = unt.id (+) and ((null IS NULL) OR (inv.MANAGER_ID = null)) and ((null IS NULL) OR (odf.eri_cfr = null)) and ((null IS NULL) OR (parent_odf.eri_pmo_manager = null)) and ((null IS NULL) OR (odf.eri_proj_number = null)) and ((1 IS NULL) OR (inv.is_active = 1)) and (flat.branch_unit_id = 5000420) and bms_sched_ms_date between nvl(null, trunc(add_months(sysdate, -1), 'MM')) and nvl(null, trunc(add_months(sysdate, 12), 'MM')) and 1 = 1 GROUP BY to_char(bms_sched_ms_date , 'YYYY/MM'), to_char(bms_sched_ms_date , 'Mon YYYY'), flat.branch_unit_id having sum(bms_plan_billed) > 0 union select to_char(bms_actual_date, 'YYYY/MM') as BMS_date_key, to_char(bms_actual_date, 'Mon YYYY') as BMS_date, 0 as scheduled, sum(bms_plan_billed) as actual, 'actual' as amount_type, flat.branch_unit_id obs_id from odf_ca_eri_prj_bill_mlstone bms , odf_ca_project odf , inv_investments inv , odf_ca_project parent_odf , prj_obs_associations assoc , prj_obs_units_flat flat , prj_obs_units unt where bms_actual_date is not null and bms.odf_parent_id = odf.id and odf.eri_prj_level != 1 and odf.id = inv.id and parent_odf.eri_prj_level = 1 and odf.eri_proj_number = parent_odf.eri_proj_number and inv.id = assoc.record_id (+) and assoc.table_name(+) = 'SRM_PROJECTS' and assoc.unit_id = flat.unit_id(+) and unt.type_id (+) = 5000034 and assoc.unit_id = unt.id (+) and ((null IS NULL) OR (inv.MANAGER_ID = null)) and ((null IS NULL) OR (odf.eri_cfr = null)) and ((null IS NULL) OR (parent_odf.eri_pmo_manager = null)) and ((null IS NULL) OR (odf.eri_proj_number = null)) and ((null IS NULL) OR (inv.is_active = null)) and (flat.branch_unit_id = 5000420) and bms_actual_date between nvl(null, trunc(add_months(sysdate, -1), 'MM')) and nvl(null, trunc(add_months(sysdate, 12), 'MM')) and 1 = 1 group by to_char(bms_actual_date, 'YYYY/MM'), to_char(bms_actual_date, 'Mon YYYY'), flat.branch_unit_id having sum(bms_plan_billed) > 0 order by 1 ) bms WHERE 1=1 and 1=1 group by BMS_date_key, BMS_date, bms.obs_id having 1=1 order by BMS_date_key ) q) q order by q.row_num; ALTER SESSION SET SQL_TRACE=FALSE; EXIT;

OK now that this is done a trace file is produced in the udump directory.on our database udump points to /fs0/oracle/admin/<SID>/udump

A trace file appears as a result of enabling SQL TRACE. It should be the last file created, but on a busy system you might have to grep for the SQL to find the file containing your trace.In this example the file is named

"niku_ora_1546.trc"

Now we tkprof the file to process the trace file into readable statistics. For now we'll do a simple tkprof (see the Oracle documentation for all the options, there's some very useful parameters you can pass to tkprof). we'll specify a sort parameter here to see SQL ordered by execution time.

sort=exeela

You run tkprof form the Linux commandline.

tkprof niku_ora_1546.trc myoutputlog.log sort=exeela

and the resulting trace file looks like this:

TKPROF: Release 10.2.0.5.0 - Production on Wed Dec 1 22:06:07 2010 

Copyright (c) 1982, 2007, Oracle.  All rights reserved. 

Trace file: niku_ora_5334.trc 
Sort options: exeela  
******************************************************************************** 
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 * from (select row_number() over ( order by key  asc) row_num, count(*) over () num_rows, q.* from ( SELECT  bms.bms_date_key key, 
        bms.bms_date bms_date, 
        sum(bms.scheduled) scheduled, 
        sum(bms.actual) actual, 
        bms.obs_id obs 
FROM 
( 
  select to_char(bms_sched_ms_date , :"SYS_B_00") as BMS_date_key, 
       to_char(bms_sched_ms_date , :"SYS_B_01") as BMS_date, 
       sum(bms_plan_billed) as scheduled, 
       :"SYS_B_02" as actual, 
       :"SYS_B_03" as amount_type, 
       flat.branch_unit_id obs_id 
  from odf_ca_eri_prj_bill_mlstone bms 
     , odf_ca_project odf 
     , inv_investments inv 
     , odf_ca_project parent_odf 
     , prj_obs_associations assoc 
     , prj_obs_units_flat flat 
     , prj_obs_units unt 
  where bms_sched_ms_date  is not null 
    and bms.bms_actual_date is null 
    and bms.odf_parent_id = odf.id 
    and odf.eri_prj_level != :"SYS_B_04" 
    and odf.id = inv.id 
    and parent_odf.eri_prj_level = :"SYS_B_05" 
    and odf.eri_proj_number = parent_odf.eri_proj_number 
    and inv.id = assoc.record_id (+) 
    and assoc.table_name(+) = :"SYS_B_06" 
    and assoc.unit_id = flat.unit_id(+) 
    and unt.type_id (+) = :"SYS_B_07" 
    and assoc.unit_id = unt.id (+) 
    and ((null IS NULL) OR (inv.MANAGER_ID = null)) 
    and ((null IS NULL) OR (odf.eri_cfr = null)) 
    and ((null IS NULL) OR (parent_odf.eri_pmo_manager = null)) 
    and ((null IS NULL) OR (odf.eri_proj_number = null)) 
    and ((:"SYS_B_08" IS NULL) OR (inv.is_active = :"SYS_B_09")) 
    and (flat.branch_unit_id = :"SYS_B_10") 
    and bms_sched_ms_date between 
    nvl(null, trunc(add_months(sysdate, -:"SYS_B_11"), :"SYS_B_12")) 
    and nvl(null, trunc(add_months(sysdate, :"SYS_B_13"), :"SYS_B_14")) 
and :"SYS_B_15" = :"SYS_B_16" 
  GROUP BY to_char(bms_sched_ms_date , :"SYS_B_17"), 
           to_char(bms_sched_ms_date , :"SYS_B_18"), 
           flat.branch_unit_id 
  having sum(bms_plan_billed) > :"SYS_B_19" 
union 
  select to_char(bms_actual_date, :"SYS_B_20") as BMS_date_key, 
       to_char(bms_actual_date, :"SYS_B_21") as BMS_date, 
       :"SYS_B_22" as scheduled, 
       sum(bms_plan_billed) as actual, 
       :"SYS_B_23" as amount_type, 
       flat.branch_unit_id obs_id 
  from odf_ca_eri_prj_bill_mlstone bms 
     , odf_ca_project odf 
     , inv_investments inv 
     , odf_ca_project parent_odf 
     , prj_obs_associations assoc 
     , prj_obs_units_flat flat 
     , prj_obs_units unt 
  where bms_actual_date is not null 
    and bms.odf_parent_id = odf.id 
    and odf.eri_prj_level != :"SYS_B_24" 
    and odf.id = inv.id 
    and parent_odf.eri_prj_level = :"SYS_B_25" 
    and odf.eri_proj_number = parent_odf.eri_proj_number 
    and inv.id = assoc.record_id (+) 
    and assoc.table_name(+) = :"SYS_B_26" 
    and assoc.unit_id = flat.unit_id(+) 
    and unt.type_id (+) = :"SYS_B_27" 
    and assoc.unit_id = unt.id (+) 
    and ((null IS NULL) OR (inv.MANAGER_ID = null)) 
    and ((null IS NULL) OR (odf.eri_cfr = null)) 
    and ((null IS NULL) OR (parent_odf.eri_pmo_manager = null)) 
    and ((null IS NULL) OR (odf.eri_proj_number = null)) 
    and ((null IS NULL) OR (inv.is_active = null)) 
    and (flat.branch_unit_id = :"SYS_B_28") 
    and bms_actual_date between 
    nvl(null, trunc(add_months(sysdate, -:"SYS_B_29"), :"SYS_B_30")) 
    and nvl(null, trunc(add_months(sysdate, :"SYS_B_31"), :"SYS_B_32")) 
and :"SYS_B_33" = :"SYS_B_34" 
  group by to_char(bms_actual_date, :"SYS_B_35"), 
           to_char(bms_actual_date, :"SYS_B_36"), 
           flat.branch_unit_id 
  having sum(bms_plan_billed) > :"SYS_B_37" 
  order by :"SYS_B_38" 
) bms 
WHERE 
      :"SYS_B_39"=:"SYS_B_40" and :"SYS_B_41"=:"SYS_B_42"  group by BMS_date_key, BMS_date, bms.obs_id 
having :"SYS_B_43"=:"SYS_B_44"  order by BMS_date_key ) q) q order by q.row_num 

call     count       cpu    elapsed       disk      query    current        rows 
------- ------  -------- ---------- ---------- ---------- ----------  ---------- 
Parse        1      0.00       0.00          0          0          0           0 
Execute      1      0.12       0.12          0          0          0           0 
Fetch        2      4.04       3.94          0     776096          0          14 
------- ------  -------- ---------- ---------- ---------- ----------  ---------- 
total        4      4.17       4.08          0     776096          0          14 

Misses in library cache during parse: 1 
Optimizer mode: ALL_ROWS 
Parsing user id: 154  (SST088P) 

Rows     Row Source Operation 
-------  --------------------------------------------------- 
     14  SORT ORDER BY (cr=776096 pr=0 pw=0 time=3949989 us) 
     14   VIEW  (cr=776096 pr=0 pw=0 time=3949997 us) 
     14    WINDOW BUFFER (cr=776096 pr=0 pw=0 time=3949995 us) 
     14     VIEW  (cr=776096 pr=0 pw=0 time=3949908 us) 
     14      FILTER  (cr=776096 pr=0 pw=0 time=3949905 us) 
     14       SORT GROUP BY (cr=776096 pr=0 pw=0 time=3949904 us) 
     16        FILTER  (cr=776096 pr=0 pw=0 time=3949862 us) 
     16         VIEW  (cr=776096 pr=0 pw=0 time=3949844 us) 
     16          SORT UNIQUE (cr=776096 pr=0 pw=0 time=3949843 us) 
     16           UNION-ALL  (cr=776096 pr=0 pw=0 time=3035250 us) 
     14            FILTER  (cr=580904 pr=0 pw=0 time=3035236 us) 
     14             HASH GROUP BY (cr=580904 pr=0 pw=0 time=3035235 us) 
 196316              FILTER  (cr=580904 pr=0 pw=0 time=2544565 us) 
 196316               HASH JOIN  (cr=580904 pr=0 pw=0 time=2544560 us) 
 196316                HASH JOIN RIGHT OUTER (cr=417940 pr=0 pw=0 time=2304384 us) 
     18                 TABLE ACCESS BY INDEX ROWID PRJ_OBS_UNITS (cr=2 pr=0 pw=0 time=102 us) 
     18                  INDEX RANGE SCAN PRJ_OBS_UNITS_N1 (cr=1 pr=0 pw=0 time=27 us)(object id 219387) 
 196316                 HASH JOIN  (cr=417938 pr=0 pw=0 time=2303641 us) 
 201342                  TABLE ACCESS FULL ODF_CA_ERI_PRJ_BILL_MLSTONE (cr=9989 pr=0 pw=0 time=201389 us) 
 133008                  NESTED LOOPS  (cr=407949 pr=0 pw=0 time=1512354 us) 
 134735                   HASH JOIN  (cr=3945 pr=0 pw=0 time=582696 us) 
 213994                    NESTED LOOPS  (cr=1301 pr=0 pw=0 time=83 us) 
     18                     TABLE ACCESS BY INDEX ROWID PRJ_OBS_UNITS_FLAT (cr=2 pr=0 pw=0 time=85 us) 
     18                      INDEX RANGE SCAN PRJ_OBS_UNITS_FLAT_N2 (cr=1 pr=0 pw=0 time=21 us)(object id 219392) 
 213994                     INDEX RANGE SCAN PRJ_OBS_ASSOCIATIONS_PK (cr=1299 pr=0 pw=0 time=123 us)(object id 219373) 
 134752                    VIEW  index$_join$_006 (cr=2644 pr=0 pw=0 time=358117 us) 
 214032                     HASH JOIN  (cr=2644 pr=0 pw=0 time=437592 us) 
 214032                      HASH JOIN  (cr=1762 pr=0 pw=0 time=63493 us) 
 214032                       INDEX FAST FULL SCAN INV_INVESTMENTS_PK (cr=628 pr=0 pw=0 time=58 us)(object id 219670) 
 214032                       INDEX FAST FULL SCAN INV_INVESTMENTS_N4 (cr=1134 pr=0 pw=0 time=39 us)(object id 219676) 
 214032                      INDEX FAST FULL SCAN INV_INVESTMENTS_U2 (cr=882 pr=0 pw=0 time=178 us)(object id 219672) 
 133008                   TABLE ACCESS BY INDEX ROWID ODF_CA_PROJECT (cr=404004 pr=0 pw=0 time=939830 us) 
 134735                    INDEX UNIQUE SCAN ODF_CA_PROJECT_PK (cr=134737 pr=0 pw=0 time=228346 us)(object id 219748) 
   2189                TABLE ACCESS FULL ODF_CA_PROJECT (cr=162964 pr=0 pw=0 time=179453 us) 
      2            FILTER  (cr=195192 pr=0 pw=0 time=914578 us) 
      2             HASH GROUP BY (cr=195192 pr=0 pw=0 time=914577 us) 
   6080              FILTER  (cr=195192 pr=0 pw=0 time=589795 us) 
   6080               HASH JOIN  (cr=195192 pr=0 pw=0 time=583705 us) 
   6080                HASH JOIN RIGHT OUTER (cr=32228 pr=0 pw=0 time=551376 us) 
     18                 TABLE ACCESS BY INDEX ROWID PRJ_OBS_UNITS (cr=2 pr=0 pw=0 time=39 us) 
     18                  INDEX RANGE SCAN PRJ_OBS_UNITS_N1 (cr=1 pr=0 pw=0 time=13 us)(object id 219387) 
   6080                 HASH JOIN  (cr=32226 pr=0 pw=0 time=551195 us) 
     18                  TABLE ACCESS BY INDEX ROWID PRJ_OBS_UNITS_FLAT (cr=2 pr=0 pw=0 time=28 us) 
     18                   INDEX RANGE SCAN PRJ_OBS_UNITS_FLAT_N2 (cr=1 pr=0 pw=0 time=6 us)(object id 219392) 
   6080                  HASH JOIN  (cr=32224 pr=0 pw=0 time=544957 us) 
   6080                   HASH JOIN  (cr=30876 pr=0 pw=0 time=571553 us) 
   6080                    NESTED LOOPS  (cr=28232 pr=0 pw=0 time=346771 us) 
   6080                     TABLE ACCESS FULL ODF_CA_ERI_PRJ_BILL_MLSTONE (cr=9989 pr=0 pw=0 time=304197 us) 
   6080                     TABLE ACCESS BY INDEX ROWID ODF_CA_PROJECT (cr=18243 pr=0 pw=0 time=38567 us) 
   6080                      INDEX UNIQUE SCAN ODF_CA_PROJECT_PK (cr=6082 pr=0 pw=0 time=11711 us)(object id 219748) 
 214032                    VIEW  index$_join$_013 (cr=2644 pr=0 pw=0 time=199949 us) 
 214032                     HASH JOIN  (cr=2644 pr=0 pw=0 time=199948 us) 
 214032                      HASH JOIN  (cr=1762 pr=0 pw=0 time=56601 us) 
 214032                       INDEX FAST FULL SCAN INV_INVESTMENTS_PK (cr=628 pr=0 pw=0 time=22 us)(object id 219670) 
 214032                       INDEX FAST FULL SCAN INV_INVESTMENTS_N4 (cr=1134 pr=0 pw=0 time=22 us)(object id 219676) 
 214032                      INDEX FAST FULL SCAN INV_INVESTMENTS_U2 (cr=882 pr=0 pw=0 time=22 us)(object id 219672) 
 213994                   INDEX FAST FULL SCAN PRJ_OBS_ASSOCIATIONS_PK (cr=1348 pr=0 pw=0 time=55 us)(object id 219373) 
   2189                TABLE ACCESS FULL ODF_CA_PROJECT (cr=162964 pr=0 pw=0 time=175074 us) 

error during execute of EXPLAIN PLAN statement 
ORA-01785: ORDER BY item must be the number of a SELECT-list expression 

parse error offset: 3636 
******************************************************************************** 

ALTER SESSION SET SQL_TRACE=FALSE 


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        0      0.00       0.00          0          0          0           0 
------- ------  -------- ---------- ---------- ---------- ----------  ---------- 
total        2      0.00       0.00          0          0          0           0 

Misses in library cache during parse: 1 
Optimizer mode: ALL_ROWS 
Parsing user id: 154  (SST088P) 



******************************************************************************** 

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS 

call     count       cpu    elapsed       disk      query    current        rows 
------- ------  -------- ---------- ---------- ---------- ----------  ---------- 
Parse        2      0.00       0.00          0          0          0           0 
Execute      2      0.12       0.12          0          0          0           0 
Fetch        2      4.04       3.94          0     776096          0          14 
------- ------  -------- ---------- ---------- ---------- ----------  ---------- 
total        6      4.17       4.08          0     776096          0          14 

Misses in library cache during parse: 2 


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS 

call     count       cpu    elapsed       disk      query    current        rows 
------- ------  -------- ---------- ---------- ---------- ----------  ---------- 
Parse        0      0.00       0.00          0          0          0           0 
Execute      0      0.00       0.00          0          0          0           0 
Fetch        0      0.00       0.00          0          0          0           0 
------- ------  -------- ---------- ---------- ---------- ----------  ---------- 
total        0      0.00       0.00          0          0          0           0 

Misses in library cache during parse: 0 

    2  user  SQL statements in session. 
    0  internal SQL statements in session. 
    2  SQL statements in session. 
    0  statements EXPLAINed in this session. 
******************************************************************************** 
Trace file: niku_ora_5334.trc 
Trace file compatibility: 10.01.00 
Sort options: exeela  
       1  session in tracefile. 
       2  user  SQL statements in trace file. 
       0  internal SQL statements in trace file. 
       2  SQL statements in trace file. 
       2  unique SQL statements in trace file. 
     408  lines in trace file. 
       4  elapsed seconds in trace file. 

From this we can see the execution plan, the timing, literally everything about the SQL statement in question.
 
Don't forget to turn tracing off with this command from the SQL prompt
 
 
ALTER SESSION SET SQL_TRACE=FALSE;