10g Consolidated Trace Files and PX

At the end of my Tracing Parallel Execution presentation at the Scottish OUG conference, Michael Møller of Miracle asked whether the consolidated trace files produced by the DBMS_MONITOR package and trcsess utility are in strict time order. i.e. Will I see the actions of the query coordinator, then the actions that the slaves perform on it’s behalf, then the qc acting on the results, then the slaves returning more results and so on. At the time, I hazarded a guess that they were (because that would sense) but said I would check properly.

Because I’m only interested in functionality and not performance, the test can be a very small scale variation of the performance tests I’ve run previously. The test table contains half a million rows in 8K blocks leading to a 64Mb data segment. There are no indexes on the table. First, I set up the client_id and enable tracing at the session level.

$ uname -a
SunOS ISP4400 5.10 Generic_118855-14 i86pc i386 i86pc
$ sqlplus testuser/testuser;

SQL*Plus: Release 10.2.0.2.0 - Production on Sun Oct 29 13:28:55 2006

Copyright (c) 1982, 2005, Oracle.  All Rights Reserved.


Connected to:
Oracle Database 10g Enterprise Edition Release 10.2.0.2.0 - Production
With the Partitioning, OLAP and Data Mining options


SQL> exec dbms_session.set_identifier('doug_test');

PL/SQL procedure successfully completed.

SQL> exec dbms_monitor.client_id_trace_enable(client_id => 'doug_test');

PL/SQL procedure successfully completed.

Next I’ll force a simple parallel full table scan using parallel degree 2. My intention here is to simplify the resulting trace output as much as possible.

SQL> set timing on
SQL> SELECT /*+ parallel(tt1, 2) */    COUNT(*)
  2  FROM test_tab1 tt1
  3  /

  COUNT(*)
----------
    512000

Elapsed: 00:00:00.80

SQL> set timing off

Just a quick check that PX was used in this session.

SQL> SELECT dfo_number, tq_id, server_type, process, num_rows, bytes
  2  FROM v$pq_tqstat
  3  ORDER BY dfo_number DESC, tq_id, server_type DESC , process;

DFO_NUMBER      TQ_ID SERVER_TYPE
---------- ---------- ------------------------------
PROCESS                          NUM_ROWS      BYTES
------------------------------ ---------- ----------
         1          0 Producer
P000                                    1         32

         1          0 Producer
P001                                    1         32

         1          0 Consumer
QC                                      2         64

Oracle has produced three trace files. One in user_dump_dest for the query co-ordinator …

$ cd /oracle/admin/TEST1020/udump
$ ls -ltra
total 676
drwxr-xr-x   7 oracle   oinstall     512 Oct  7 11:54 ..
drwxr-xr-x   2 oracle   oinstall    1536 Oct 29 13:29 .
-rw-r-----   1 oracle   oinstall   35340 Oct 29 13:36 test1020_ora_2663.trc

… and two in background_dump_dest for the two PX slaves …

$ cd ../bdump
$ ls -ltra
total 3084
drwxr-xr-x   7 oracle   oinstall     512 Oct  7 11:54 ..
-rw-r--r--   1 oracle   oinstall  141715 Oct 29 12:43 alert_TEST1020.log
drwxr-xr-x   2 oracle   oinstall    2560 Oct 29 13:31 .
-rw-r-----   1 oracle   oinstall  562054 Oct 29 13:33 test1020_p000_2666.trc
-rw-r-----   1 oracle   oinstall  694551 Oct 29 13:33 test1020_p001_2668.trc

The next task is to generate the consolidated trace file that will include all of the actions for client_id doug_test from all three trace files.

$ trcsess output="doug_test.trc" clientid="doug_test" /oracle/admin/TEST1020/udump/*.trc \ 
	/oracle/admin/TEST1020/bdump/*.trc
$ ls -ltra doug_test.trc
-rw-r--r--   1 oracle   oinstall 1717274 Oct 29 13:40 doug_test.trc

Now to find out if the consolidated trace file is in strict time order. I’m going to snip out tons of inrellevant information and only look at the steps specific to the SELECT COUNT(*). The QC is first. I’ve highlighted the wall clock ‘tim’ values

PARSING IN CURSOR #8 len=138 dep=0 uid=27 oct=3 lid=27 tim=88193242894 
	hv=1002038861 ad='918fe164'
SELECT /*+ parallel(tt1, 2) */
-- MOD(tt1.pk_id, 2),
COUNT(*)
FROM test_tab3 tt1
-- GROUP BY MOD(tt1.pk_id,2)
-- ORDER BY MOD(tt1.pk_id,2)
END OF STMT
PARSE #8:c=170000,e=244171,p=9,cr=265,cu=3,mis=1,r=0,dep=0,og=1,tim=88193242884
WAIT #8: nam='db file sequential read' ela= 14281 file#=6 block#=2236425 
	blocks=1 obj#=10660 tim=88193261507
WAIT #8: nam='PX Deq: Join ACK' ela= 2053 sleeptime/senderid=268500992 
	passes=1 p3=0 obj#=10660 tim=88193268968
WAIT #8: nam='PX Deq: Parse Reply' ela= 4 sleeptime/senderid=200 
	passes=1 p3=0 obj#=10660 tim=88193276000
WAIT #8: nam='PX Deq: Parse Reply' ela= 24043 sleeptime/senderid=200 
	passes=2 p3=0 obj#=10660 tim=88193300120
EXEC #8:c=20000,e=61590,p=1,cr=3,cu=0,mis=0,r=0,dep=0,og=1,tim=88193304745

Next I’m going to skip over a large bunch of PX Execute Reply wait events that appear next, as the QC waits for results to be returned from the slave processes (which almost provides the answer to Michael’s question already), to take a look at the start of the slave activity.

PARSING IN CURSOR #1 len=138 dep=1 uid=27 oct=3 lid=27 tim=88193297955 
	hv=1002038861 ad='918fe164'
SELECT /*+ parallel(tt1, 2) */
-- MOD(tt1.pk_id, 2),
COUNT(*)
FROM test_tab3 tt1
-- GROUP BY MOD(tt1.pk_id,2)
-- ORDER BY MOD(tt1.pk_id,2)
END OF STMT
PARSE #1:c=0,e=1948,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=88193297879
WAIT #1: nam='PX Deq: Execution Msg' ela= 2354 sleeptime/senderid=268566527 
	passes=1 p3=0 obj#=-1 tim=88193304777

I can see that this line from the QC

WAIT #8: nam='PX Deq: Parse Reply' ela= 24043 sleeptime/senderid=200 
	passes=2 p3=0 obj#=10660 tim=88193300120

appears before this line from one of the slaves

PARSE #1:c=0,e=1948,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=88193297879

… even though it happened at a later time.

The simple answer is that trcsess does not consolidate the events into timed order rather, looking at the consolidated trace file (note that file is an unaltered section from the middle of the entire trace file), it groups together all of the actions related to a specific cursor which, in retrospect, makes much more sense even though it strikes me as being less interesting.