Adaptive STAT lines in SQL trace

Lately I’ve been using SQL runtime execution statistics combined with SQL monitor for performance diagnostics and, honestly, almost forgot about SQL trace. So this note is not very useful to me but it might be to someone: along with ALL_EXECUTIONS option appeared in (I believe) 11gR2, there’s a new option starting with 11.2.0.2 which can significantly decrease amount of data in the trace files for STAT lines compared to ALL_EXECUTIONS, still providing some of them from time to time.

Here is a case to demonstrate:

declare
    n number := 0;
begin
    dbms_session.session_trace_enable(true, true, 'all_executions');
   
    for x in 1..10 loop
        for y in (select * from all_source) loop
            n := n + length(y.text);
        end loop;
    end loop;

    dbms_session.session_trace_disable;
end;
/

And if I search through the resulting trace file, I’ll find 10 occurrences of the STAT lines for runtime execution statistics of the SQL, as desired:

C:\Users\Tim>grep "VIEW  ALL_SOURCE" d:\oracle\diag\rdbms\test\test\trace/test_ora_1660.trc
STAT #191268904 id=1 cnt=633054 pid=0 pos=1 obj=4813 op='VIEW  ALL_SOURCE (cr=39988 pr=0 pw=0 time=2369570 us cost=1039 size=569297377 card=276761)'
STAT #191268904 id=1 cnt=633054 pid=0 pos=1 obj=4813 op='VIEW  ALL_SOURCE (cr=39988 pr=0 pw=0 time=2329706 us cost=1039 size=569297377 card=276761)'
STAT #191268904 id=1 cnt=633054 pid=0 pos=1 obj=4813 op='VIEW  ALL_SOURCE (cr=39988 pr=0 pw=0 time=2351289 us cost=1039 size=569297377 card=276761)'
STAT #191268904 id=1 cnt=633054 pid=0 pos=1 obj=4813 op='VIEW  ALL_SOURCE (cr=39988 pr=0 pw=0 time=2334011 us cost=1039 size=569297377 card=276761)'
STAT #191268904 id=1 cnt=633054 pid=0 pos=1 obj=4813 op='VIEW  ALL_SOURCE (cr=39988 pr=0 pw=0 time=2350335 us cost=1039 size=569297377 card=276761)'
STAT #191268904 id=1 cnt=633054 pid=0 pos=1 obj=4813 op='VIEW  ALL_SOURCE (cr=39988 pr=0 pw=0 time=2337449 us cost=1039 size=569297377 card=276761)'
STAT #191268904 id=1 cnt=633054 pid=0 pos=1 obj=4813 op='VIEW  ALL_SOURCE (cr=39988 pr=0 pw=0 time=2340285 us cost=1039 size=569297377 card=276761)'
STAT #191268904 id=1 cnt=633054 pid=0 pos=1 obj=4813 op='VIEW  ALL_SOURCE (cr=39988 pr=0 pw=0 time=2329053 us cost=1039 size=569297377 card=276761)'
STAT #191268904 id=1 cnt=633054 pid=0 pos=1 obj=4813 op='VIEW  ALL_SOURCE (cr=39988 pr=0 pw=0 time=2362534 us cost=1039 size=569297377 card=276761)'
STAT #191268904 id=1 cnt=633054 pid=0 pos=1 obj=4813 op='VIEW  ALL_SOURCE (cr=39988 pr=0 pw=0 time=2326067 us cost=1039 size=569297377 card=276761)'

Now I’ll change the way I’m enabling trace and repeat the case in another session with 30 iterations:

alter session set events 'sql_trace wait=true, bind=true, plan_stat=adaptive';

declare
    n number := 0;
begin
    for x in 1..30 loop
        for y in (select * from all_source) loop
            n := n + length(y.text);
        end loop;
    end loop;
end;
/

alter session set events 'sql_trace off';

Using new 11g syntax for the EVENTS I’ve set PLAN_STAT option to ADAPTIVE and the plan appears two times in the trace:

C:\Users\Tim>grep "VIEW  ALL_SOURCE" d:\oracle\diag\rdbms\test\test\trace/test_ora_1788.trc
STAT #191264936 id=1 cnt=633054 pid=0 pos=1 obj=4813 op='VIEW  ALL_SOURCE (cr=39988 pr=0 pw=0 time=2337943 us cost=1039 size=569297377 card=276761)'
STAT #191264936 id=1 cnt=633054 pid=0 pos=1 obj=4813 op='VIEW  ALL_SOURCE (cr=39988 pr=0 pw=0 time=2352998 us cost=1039 size=569297377 card=276761)'

One for the first execution and the second after 18th execution of the cursor. Why 18th? It’s because per 1 execution the DB spends 2.3 seconds of time on average and after 10 + 18 executions for this child cursor the time spent by the DB has gone beyond 60 seconds and this triggered dumping execution statistics again. It should probably happened after 27th execution one might think. Most likely it relates to the time when the statistics in the V$ view is refreshed and the check is performed.
Anyway this is nice improvement to the SQL trace. Here is the bug for this improvement: Bug 8328200 – Misleading or excessive STAT# lines for SQL_TRACE / 10046. One minor issue is the new option is not available with DBMS_SESSION/DBMS_MONITOR packages and works only with EVENTS syntax – I hope it will be fixed some day, as well as documentation.

About these ads

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

Join 291 other followers