Dion Cho – Oracle Performance Storyteller

One thing very disappointing on parallel execution is the fact that the trace files of slave sessions are scattered as different files in the background dump directory.

So I built up my own script which automates the execution of tkprof on those scattered trace files.

1. pq_trace.sql generates the series of tkprof command with the input of coordinate session id.

set heading off
set timing off
set feedback off
set verify off
set serveroutput on size 100000

spool generate_pq_tkprof.sql

define __QCID = &1

declare
  v_dir     varchar2(4000);
  v_inst    varchar2(4000);
  v_trcfile varchar2(4000);
  v_cmd     varchar2(4000);
begin
  -- get dump directory
  for v in (select banner from v$version where rownum = 1) loop
    select value into v_dir from v$parameter
        where name = 'background_dump_dest';
  end loop;

  -- get instance name
  select value into v_inst from v$parameter
      where name = 'instance_name';

  -- generate series of tkprof command
  for s in (select s.sid, p.spid, rownum-1 as server#
        from v$px_session s, v$px_process p
        where
            s.sid = p.sid
            and s.qcsid in (&__QCID)
            and s.sid <> s.qcsid) loop

      v_trcfile := v_dir||'\'||v_inst||'_'||'p'||lpad(to_char(s.server#),3,'0')||
              '_'||s.spid||'.trc';
      v_cmd := 'ho tkprof ' || v_trcfile || ' trc' || '_' || s.server# || '.out';
      dbms_output.put_line(v_cmd);

  end loop;
end;
/

spool off
set heading on
set timing on
set feedback on
set verify on
set serveroutput off

ed generate_pq_tkprof

2. The output of pq_trace.sql script is stored as generate_pq_tkprof.sql as following:

ed generate_pq_tkprof.sql

ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p000_2792.trc trc_0.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p001_704.trc trc_1.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p002_4892.trc trc_2.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p003_2728.trc trc_3.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p004_1244.trc trc_4.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p005_2736.trc trc_5.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p006_4508.trc trc_6.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p007_2432.trc trc_7.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p008_3916.trc trc_8.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p009_656.trc trc_9.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p010_5308.trc trc_10.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p011_4880.trc trc_11.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p012_4288.trc trc_12.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p013_4528.trc trc_13.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p014_5852.trc trc_14.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p015_2716.trc trc_15.out

3. Following is a simple demonstration.
# Session A (session id = 130)

alter session set tracefile_identifier = &1;

@trace_on 10046 8

select /*+ parallel(t1 8) */ count(*) from t1, t1
where rownum <= 500000
;

@trace_off

# Session B
While session A executes parallel query

 @pq_trace 130   -- 130 is id of session A

After the parallel query of session A completes.

UKJA@ukja102> @generate_pq_tkprof

TKPROF: Release 11.1.0.6.0 - Production on Thu Mar 12 16:41:06 2009

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

UKJA@ukja102> ed trc_5.out

select /*+ parallel(t1 8) */ count(*) from t1, t1
where rownum <= 500000

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1     14.18      58.32          0         16          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2     14.18      58.32          0         16          0           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 61     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  SORT AGGREGATE (cr=0 pr=0 pw=0 time=0 us)
      0   COUNT STOPKEY (cr=0 pr=0 pw=0 time=0 us)
      0    PX COORDINATOR  (cr=0 pr=0 pw=0 time=0 us)
      0     PX SEND QC (RANDOM) :TQ10001 (cr=0 pr=0 pw=0 time=0 us)
 500000      COUNT STOPKEY (cr=16 pr=0 pw=0 time=52514746 us)
 500000       MERGE JOIN CARTESIAN (cr=16 pr=0 pw=0 time=32514719 us)
    345        SORT JOIN (cr=0 pr=0 pw=0 time=894433 us)
  10000         PX RECEIVE  (cr=0 pr=0 pw=0 time=701281 us)
      0          PX SEND BROADCAST :TQ10000 (cr=0 pr=0 pw=0 time=0 us)
      0           PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us)
      0            TABLE ACCESS FULL T1 (cr=0 pr=0 pw=0 time=0 us)
 500000        BUFFER SORT (cr=16 pr=0 pw=0 time=13119697 us)
   1452         PX BLOCK ITERATOR (cr=16 pr=0 pw=0 time=118476 us)
   1452          TABLE ACCESS FULL T1 (cr=16 pr=0 pw=0 time=53795 us)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PX Deq: Execution Msg                           6        0.05          0.09
  PX Deq: Table Q Normal                          3        0.09          0.09
  PX Deq Credit: send blkd                        2        0.00          0.00
  PX qref latch                                   2        0.00          0.00

These kinds of automation techniques are really time and even life savers. :)