At the end of my Tracing Parallel Execution presentation at the Scottish OUG conference, Michael M\u00f8ller 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.<\/p>\n
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.<\/p>\n
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.<\/p>\n Just a quick check that PX was used in this session.<\/p>\n Oracle has produced three trace files. One in user_dump_dest for the query co-ordinator …<\/p>\n … and two in background_dump_dest for the two PX slaves …<\/p>\n 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.<\/p>\n 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<\/p>\n 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.<\/p>\n I can see that this line from the QC <\/p>\n appears before this line from one of the slaves<\/p>\n … even though it happened at a later time.<\/p>\n The simple answer is that trcsess does not consolidate the events into timed order rather, looking at the consolidated trace file<\/a> (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.<\/p>\n","protected":false},"excerpt":{"rendered":"<\/code><\/p>\n$ uname -a
<\/code><\/p>\nSQL> set timing on
<\/code><\/p>\nSQL> SELECT dfo_number, tq_id, server_type, process, num_rows, bytes
<\/code><\/p>\n$ cd \/oracle\/admin\/TEST1020\/udump
<\/code><\/p>\n<\/code><\/p>\n$ trcsess output=\"doug_test.trc\" clientid=\"doug_test\" \/oracle\/admin\/TEST1020\/udump\/*.trc \\
<\/code><\/p>\nPARSING IN CURSOR #8 len=138 dep=0 uid=27 oct=3 lid=27 tim=88193242894<\/b><\/i>
<\/code><\/p>\nPARSING IN CURSOR #1 len=138 dep=1 uid=27 oct=3 lid=27 tim=88193297955<\/b><\/i>
<\/code><\/p>\nWAIT #8: nam='PX Deq: Parse Reply' ela= 24043 sleeptime\/senderid=200
<\/code><\/p>\nPARSE #1:c=0,e=1948,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=88193297879<\/b><\/i><\/pre>\n