Profiling trace files with preprocessor external tables in 11g and some parallel execution hacking

If you work with SQL Trace files (and profile them) then you should check out the awesome novel use of the “external table preprocessor” feature explained by Adrian Billington here:

http://www.oracle-developer.net/display.php?id=516

Ironically just a day after writing my “Evil things” article, I noticed a note in MOS about how to enable an event 10384 at level 16384 to get a parallel plan to be executed in serial:

How to force that a Parallel Query runs in serial with the Parallel Execution Plan [ID 1114405.1]

This way you can still see the A-rows and other feedback like buffer gets and PIOs by row source even if the plan is a parallel plan. The problem is that even with GATHER_PLAN_STATISTICS enabled (or the equivalent parameter(s)) the PX slaves don’t pass their actual time, rows and buffer gets/PIOs stats back to the QC to be displayed in V$SQL_PLAN_STATISTICS / DBMS_XPLAN output. With parallel slaves, all you’d see would be the QC-generated numbers and not the PX slave stuff.

So if you set that magic event (at your own risk) then even the parallel plans would be executed by the QC only (basically a parallel plan executed entirely ins serial) and you’ll still see all the A-rows and buffer gets/physical read numbers as with serial plans. But remember my yesterday’s article ;-)

Alternative options for getting such runtime stats for a parallel query would be:

Use the Real-Time SQL Monitoring feature (only on 11g and with diagnostics+tuning pack licenses)
Enable SQL Trace for the QC, run your parallel query (you’ll have to wait until it finishes or cancel the query with CTRL+C) and consolidate the STAT# lines from all the PX slave sessions – each PX slave dumps the STAT# lines with row-source level stats like regular serial queries

Update: Coskan commented over twitter that why not use ALLSTATS ALL in DBMS_XPLAN.DISPLAY_CURSOR instead of ALLSTATS LAST – and indeed, in this case you would see the A-rows, buffer gets and other stats of both QC and the PX slaves aggregated together. Although I had used ALLSTATS ALL to compare average execution stats to the LAST stats, I never thought of using it for aggregating the PX slave stats together with QC like that.

Basically what happens (in 10g+) with PX is that the QC and all PX slaves all execute the same SQL_ID (but sometimes a different child version though, especially when you’re running cross-instance PX, in which case SQL Monitoring is a better option). And ALLSTATS ALL would aggregate the stats of all executions of the particular SQL_ID (and child number). So if you run something with 4 PX slaves with GATHER_PLAN_STATISTICS enabled, they all add their execution stats to the “ALL” columns. It’s just that the QC is always the last one to finish executing the query (that’s when the exec stats get updated in the V$SQL_PLAN_STATISTICS views), that’s why the ALLSTATS LAST always shows the limited QC stats and not the PX slave ones. But Allstats ALL solves that problem.

However the catch is that ALLSTATS ALL would accumulate all executions of this query (including your previous runs of it), so if you want to see fresh stats of only your latest query execution, you should adjust the SQL_ID so that a new cursor would be created. And you can adjust the SQL_ID by simply adding a comment like /* test 2 */ somewhere into your query text…

Thanks Coskan! :)

Profiling trace files with preprocessor external tables in 11g and some parallel execution hacking

Tanel Poder

2011-11-14