Testing Autotrace
In response to a remark I made on a posting about autotrace, Howard Rogers asked me to supply a demonstration of the fact that the “traceonly explain” option simply executes a call to explain plan (which means the resulting plan may be a lie), and doesn’t actually run the target SQL statement in the special case that the SQL statement is a select statement.
So here’s a very simple test script:
execute dbms_random.seed(0)
drop table t1;
create table t1 as
select
rownum id,
trunc(dbms_random.value(1,50)) n1,
rpad('x',100) padding
from
all_objects
where
rownum <= 1000
;
create index t1_i1 on t1(n1);
begin
dbms_stats.gather_table_stats(
ownname => user,
tabname =>'T1',
cascade => true,
estimate_percent => null,
granularity => 'default',
method_opt => 'for all columns size 1'
);
end;
/
variable m_n1 number
execute :m_n1 := 0;
set autotrace traceonly explain
alter session set events '10046 trace name context forever, level 1';
select id from t1 where n1 > :m_n1;
alter session set events '10046 trace name context off';
set autotrace traceonly
select id from t1 where n1 > :m_n1;
set autotrace off
exit
And here’s the content of the trace file - running under 9.2.0.6 database - with a few lines highlighted:
*** 2006-11-29 08:51:00.619
*** SESSION ID:(10.5540) 2006-11-29 08:51:00.619
APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240
=====================
PARSING IN CURSOR #1 len=68 dep=0 uid=64 oct=42 lid=64 tim=952001035087 hv=3636843312 ad='6e70b88c'
alter session set events '10046 trace name context forever, level 1'
END OF STMT
EXEC #1:c=0,e=74,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=952001032059
=====================
PARSING IN CURSOR #1 len=34 dep=0 uid=64 oct=3 lid=64 tim=952001042171 hv=3315653934 ad=’6e6c64ac’
select id from t1 where n1 > :m_n1
END OF STMT
PARSE #1:c=0,e=891,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=0,tim=952001042164
=====================
PARSING IN CURSOR #1 len=45 dep=0 uid=64 oct=7 lid=64 tim=952001044671 hv=1983591574 ad=’6dd243a4′
DELETE FROM PLAN_TABLE WHERE STATEMENT_ID=:1
END OF STMT
PARSE #1:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=952001044664
EXEC #1:c=0,e=89,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=952001045804
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op=’DELETE ‘
STAT #1 id=2 cnt=0 pid=1 pos=1 obj=44938 op=’TABLE ACCESS FULL PLAN_TABLE$ ‘
=====================
PARSING IN CURSOR #1 len=79 dep=0 uid=64 oct=50 lid=64 tim=952001053754 hv=629220253 ad=’6e6ab7c0′
EXPLAIN PLAN SET STATEMENT_ID=’PLUS6717′ FOR select id from t1 where n1 > :m_n1
END OF STMT
PARSE #1:c=0,e=1235,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=952001053747
=====================
PARSING IN CURSOR #12 len=477 dep=1 uid=64 oct=2 lid=64 tim=952001054780 hv=2369813480 ad=’6daf9e34′
insert into plan_table (statement_id, timestamp, operation, options,object_node, object_owner, object_name, object_instance, object_type,search_columns, id, parent_id, position, other,optimizer, cost, cardinality, bytes, other_tag, partition_start, partition_stop, partition_id, distribution, cpu_cost, io_cost, temp_space, access_predicates, filter_predicates ) values(:1,SYSDATE,:2,:3,:4,:5,:6,:7,:8,:9,:10,:11,:12,:13,:14,:15,:16,:17,:18,:19,:20,:21,:22,:23,:24,:25,:26,:27)
END OF STMT
PARSE #12:c=0,e=78,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=952001054774
=====================
PARSING IN CURSOR #13 len=85 dep=1 uid=0 oct=3 lid=0 tim=952001055674 hv=3273384892 ad=’6e12e644′
select o.name, u.name from sys.obj$ o, sys.user$ u where obj# = :1 and owner# = user#
END OF STMT
PARSE #13:c=0,e=53,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,tim=952001055668
EXEC #12:c=0,e=459,p=0,cr=1,cu=8,mis=0,r=1,dep=1,og=4,tim=952001057094
EXEC #12:c=0,e=165,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=4,tim=952001057745
EXEC #12:c=0,e=157,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=4,tim=952001058371
EXEC #1:c=0,e=4141,p=0,cr=1,cu=10,mis=0,r=0,dep=0,og=4,tim=952001058765
=====================
PARSING IN CURSOR #1 len=637 dep=0 uid=64 oct=3 lid=64 tim=952001060145 hv=904454640 ad=’6e127ebc’
SELECT ID ID_PLUS_EXP,PARENT_ID PARENT_ID_PLUS_EXP,LPAD(’ ‘,2*(LEVEL-1))||OPERATION||DECODE(OTHER_TAG,NULL,”,’*')||DECODE(OPTIONS,NULL,”,’ (’||OPTIONS||’)')||DECODE(OBJECT_NAME,NULL,”,’ OF ”’||OBJECT_NAME||””)||DECODE(OBJECT_TYPE,NULL,”,’ (’||OBJECT_TYPE||’)')||DECODE(ID,0,DECODE(OPTIMIZER,NULL,”,’ Optimizer=’||OPTIMIZER))||DECODE(COST,NULL,”,’ (Cost=’||COST||DECODE(CARDINALITY,NULL,”,’ Card=’||CARDINALITY)||DECODE(BYTES,NULL,”,’ Bytes=’||BYTES)||’)') PLAN_PLUS_EXP,OBJECT_NODE OBJECT_NODE_PLUS_EXP FROM PLAN_TABLE START WITH ID=0 AND STATEMENT_ID=:1 CONNECT BY PRIOR ID=PARENT_ID AND STATEMENT_ID=:1 ORDER BY ID,POSITION
END OF STMT
PARSE #1:c=0,e=73,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=952001060138
EXEC #1:c=15625,e=178,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=952001061229
FETCH #1:c=0,e=455,p=0,cr=13,cu=0,mis=0,r=1,dep=0,og=4,tim=952001062012
FETCH #1:c=0,e=60,p=0,cr=0,cu=0,mis=0,r=2,dep=0,og=4,tim=952001063185
STAT #1 id=1 cnt=3 pid=0 pos=1 obj=0 op=’SORT ORDER BY ‘
STAT #1 id=2 cnt=3 pid=1 pos=1 obj=0 op=’CONNECT BY WITH FILTERING ‘
STAT #1 id=3 cnt=1 pid=2 pos=1 obj=0 op=’NESTED LOOPS ‘
STAT #1 id=4 cnt=1 pid=3 pos=1 obj=44938 op=’TABLE ACCESS FULL PLAN_TABLE$ ‘
STAT #1 id=5 cnt=1 pid=3 pos=2 obj=44938 op=’TABLE ACCESS BY USER ROWID PLAN_TABLE$ ‘
STAT #1 id=6 cnt=2 pid=2 pos=2 obj=0 op=’NESTED LOOPS ‘
STAT #1 id=7 cnt=3 pid=6 pos=1 obj=0 op=’BUFFER SORT ‘
STAT #1 id=8 cnt=3 pid=7 pos=1 obj=0 op=’CONNECT BY PUMP ‘
STAT #1 id=9 cnt=2 pid=6 pos=2 obj=44938 op=’TABLE ACCESS FULL PLAN_TABLE$ ‘
=====================
PARSING IN CURSOR #1 len=148 dep=0 uid=64 oct=3 lid=64 tim=952001078682 hv=2972539658 ad=’6d909614′
SELECT ID ID_PLUS_EXP,OTHER_TAG OTHER_TAG_PLUS_EXP,OTHER OTHER_PLUS_EXP FROM PLAN_TABLE WHERE STATEMENT_ID=:1 AND OTHER_TAG IS NOT NULL ORDER BY ID
END OF STMT
PARSE #1:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=952001078675
EXEC #1:c=0,e=76,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=952001079581
FETCH #1:c=0,e=129,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=4,tim=952001080454
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op=’SORT ORDER BY ‘
STAT #1 id=2 cnt=0 pid=1 pos=1 obj=44938 op=’TABLE ACCESS FULL PLAN_TABLE$ ‘
=====================
PARSING IN CURSOR #1 len=45 dep=0 uid=64 oct=7 lid=64 tim=952001084781 hv=1983591574 ad=’6dd243a4′
DELETE FROM PLAN_TABLE WHERE STATEMENT_ID=:1
END OF STMT
PARSE #1:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=952001084775
EXEC #1:c=0,e=265,p=0,cr=3,cu=3,mis=0,r=3,dep=0,og=4,tim=952001085843
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op=’DELETE ‘
STAT #1 id=2 cnt=3 pid=1 pos=1 obj=44938 op=’TABLE ACCESS FULL PLAN_TABLE$ ‘
=====================
PARSING IN CURSOR #1 len=55 dep=0 uid=64 oct=42 lid=64 tim=952001087997 hv=4110456808 ad=’6e6a92a8′
alter session set events ‘10046 trace name context off’
END OF STMT
PARSE #1:c=0,e=253,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=952001087990
EXEC #1:c=0,e=85,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=952001088970
Note particularly the lines starting with “PARSING IN CURSOR #1:”. The cursor for the target statement only gets parsed, never executed or fetched, and that cursor must be closed so that the cursor handle (#1) can be re-used for the subsequent “DELETE FROM PLAN_TABLE …”. Note also the explicit call to “EXPLAIN PLAN SET STATEMENT_ID … “.
The output for the traceonly explain call shows an index range scan, using the usual selectivity estimate of “5% for an unknown value” to get a cardinality of 50. The output from the traceonly with explain and statistics does the same - but the query actually then runs using a full table scan. Here’s the execution plan as reported in both cases, followed by the stat# lines that appear from the trace file if I allow the 10046 trace to continue to the end of the script:
Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=3 Card=50 Bytes=350)
1 0 TABLE ACCESS (BY INDEX ROWID) OF 'T1' (Cost=3 Card=50 Bytes=350)
2 1 INDEX (RANGE SCAN) OF 'T1_I1' (NON-UNIQUE) (Cost=2 Card=9)
...
FETCH #1:c=0,e=35,p=0,cr=1,cu=0,mis=0,r=24,dep=0,og=4,tim=951925289592
*** SESSION ID:(10.553 
2006-11-29 08:49:44.916
STAT #1 id=1 cnt=1000 pid=0 pos=1 obj=45035 op=’TABLE ACCESS FULL T1 ‘
Variation in 10g:
A brief extract from a 10.2.0.1 database shows an odd variation - the trace file starts with the following - but (even in the case of traceonly explain) has some surprising stat# lines near the end:
PARSING IN CURSOR #26 len=34 dep=0 uid=64 oct=3 lid=64 tim=952059761895 hv=3660235829 ad='6ca057c4'
select id from t1 where n1 > :m_n1
END OF STMT
PARSE #26:c=0,e=396,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=952059761887
=====================
PARSING IN CURSOR #7 len=45 dep=0 uid=64 oct=7 lid=64 tim=952059764606 hv=349105966 ad='6c662f70'
DELETE FROM PLAN_TABLE WHERE STATEMENT_ID=:1
END OF STMT
PARSE #7:c=0,e=87,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=952059764599
EXEC #7:c=0,e=107,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=952059765591
STAT #7 id=1 cnt=0 pid=0 pos=1 obj=0 op='DELETE PLAN_TABLE$ (cr=0 pr=0 pw=0 time=23 us)'
STAT #7 id=2 cnt=0 pid=1 pos=1 obj=8706 op='TABLE ACCESS FULL PLAN_TABLE$ (cr=0 pr=0 pw=0 time=10 us)'
=====================
PARSING IN CURSOR #26 len=79 dep=0 uid=64 oct=3 lid=64 tim=952059772360 hv=927695432 ad='6d6366d0'
EXPLAIN PLAN SET STATEMENT_ID='PLUS2541' FOR select id from t1 where n1 > :m_n1
END OF STMT
PARSE #26:c=0,e=436,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=952059772353
=====================
...
EXEC #26:c=15625,e=12248,p=0,cr=2,cu=25,mis=1,r=0,dep=0,og=1,tim=952059785517
STAT #26 id=1 cnt=0 pid=0 pos=1 obj=68966 op='TABLE ACCESS BY INDEX ROWID T1 (cr=0 pr=0 pw=0 time=0 us)'
STAT #26 id=2 cnt=0 pid=1 pos=1 obj=68967 op='INDEX RANGE SCAN T1_I1 (cr=0 pr=0 pw=0 time=0 us)'
Notice that the cursor handle (#26) is re-used for the cursor “EXPLAIN PLAN …”, but at the end of the trace file, the stat# line dump for the cursor #26 seems to be back to the previous content of the cursor - the actual “select …”. (Even so, it’s still the wrong execution plan compared to the real run-time plan).
[...] I’ve just realised that “pages” probably don’t show up on the RSS feeds, and since they’re hardly noticeable in the little patch of screen to the right they may be very easy to go unnoticed. So here’s a brief note to let people know I’ve just written a new one on a test of autotrace. [...]
Pingback by Posts and Pages « Oracle Scratchpad — November 29, 2006 @ 5:40 pm UTC Nov 29,2006
I’d fix the line:
To say “the fact that the traceonly explain option …” That’s what you intended, right? (All other combinations run the query.)
Using the same configuration and SELECT query you did, I executed (and traced) the following SET AUTOTRACE settings:
set autotrace on
set autotrace traceonly
set autotrace traceonly explain
set autotrace traceonly explain statistics
All four executions printed out the plan:
Execution Plan
———————————————————-
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=3 Card=50 Bytes=350)
1 0 TABLE ACCESS (BY INDEX ROWID) OF ‘T1′ (Cost=3 Card=50 Bytes=350)
2 1 INDEX (RANGE SCAN) OF ‘T1_I1′ (NON-UNIQUE) (Cost=2 Card=9)
And yet all four executions actually used a full table scan:
STAT #1 id=1 cnt=1000 pid=0 pos=1 obj=7103 op=’TABLE ACCESS FULL T1 ‘
All three of:
set autotrace on
set autotrace traceonly
set autotrace explain statistics
actually ran the query, whereas
set autotrace explain
did not (which is what you suggest).
But all four options - autotrace on or traceonly - discovered the plan via an explain plan statement against the query, and did not return the real plan. Perhaps that was implied in the above but I thought I’d mention it here specifically.
Comment by Adam M. Donahue — November 29, 2006 @ 9:52 pm UTC Nov 29,2006
Adam, Thanks for picking up the omission - I’ve made the correction.
The grammar is not elegant, but you are correct - the point I was demonstrating was that “traceonly explain” was the special case that did not run select statements; otherwise all the options behave identically. But the intent is only clear if you happen to have read the original and Howard’s initial response.
Comment by Jonathan Lewis — November 29, 2006 @ 10:13 pm UTC Nov 29,2006
In the 9.2.0.6 example, you say “…
Note particularly the lines starting with “PARSING IN CURSOR #1:”. The cursor for the target statement only gets parsed, never executed or fetched, and that cursor must be closed so that the cursor handle (#1) can be re-used for the subsequent “DELETE FROM PLAN_TABLE …”.
…”.
However, I do notice that in the trace data there is an EXEC #1 which is associated with the EXPLAIN PLAN parse. The line which is located just above the next PARSING IN CURSOR #1 line is:
EXEC #1:c=0,e=4141,p=0,cr=1,cu=10,mis=0,r=0,dep=0,og=4,tim=952001058765
So, the correction I’d suggest is that the EXPLAIN PLAN command does have an EXEC - as it should (after all, the EXPLAIN PLAN command must be executed in order to populate the PLAN_TABLE, right?).
However, I believe your point was that Oracle executes just the EXPLAIN PLAN and doesn’t execute the actual SELECT statement and this is still clear in the trace data.
And, it’s great to have you blogging. I’m enjoying your posts!
Comment by Karen Morton — November 30, 2006 @ 4:58 pm UTC Nov 30,2006
Jonathan,
More on this CURSOR# business. Have we narrowed down the logic of exactly what generates these numbers and when and how they’re reused?
Adam
Comment by Adam M. Donahue — December 8, 2006 @ 8:11 pm UTC Dec 8,2006
Adam,
I haven’t looked at the generation and re-use. But if you want some guesses. The cursor numbers are probably just rows in an array. A row can be re-used if the cursor closes, and is not held in the pl/sql cache or the session cursor cache. In the example, the presence of the higher cursor numbers if probably due to cursors being opened and held in the pl/sql cache from previous activity.
Comment by Jonathan Lewis — December 8, 2006 @ 8:51 pm UTC Dec 8,2006
I am currently going through your CBO Fundamentals book and have set up a test 10gr2 database for going through the examples in your book.
I want to know how to get autotrace to display an execution plan as shown in your book -
Execution Plan (10.1.0.4 autotrace)
———————————————————-
0 SELECT STATEMENT Optimizer=ALL_ROWS (Cost=4 Card=200 Bytes=20600)
1 0 TABLE ACCESS (FULL) OF ‘T1′ (TABLE) (Cost=4 Card=200 Bytes=20600)
But all I get to see is this –
Execution Plan
———————————————————-
Plan hash value: 3617692013
———————————————————-
| Id | Operation | Name | Rows | Bytes | Cost |
———————————————————-
| 0 | SELECT STATEMENT | | 200 | 20600 | 4 |
|* 1 | TABLE ACCESS FULL| T1 | 200 | 20600 | 4 |
———————————————————-
Comment by prichard — April 8, 2007 @ 3:05 pm UTC Apr 8,2007
Prichard,
The format of the autotrace output changed from 10.1 to 10.2 - that’s partly why I tried to label every autotrace output in the book with the version it came from.
Autotrace in 10.2 uses a call to the dbms_xplan.display() function.
You will probably find, by the way, that some of the execution plans in the examples change when you run the test cases on 10.2 - there were a lot of changes to the optimizer in that version.
Comment by Jonathan Lewis — April 8, 2007 @ 4:03 pm UTC Apr 8,2007
How do I get autotrace to show me the parent Id column in 10gr2?
Comment by prichard — April 8, 2007 @ 4:32 pm UTC Apr 8,2007
prichard,
You can’t - it’s one of the really irritating defects of dbms_xplan.display(). You have to judge it by eye, which isn’t easy for a plan longer than a dozen lines or so.
Comment by Jonathan Lewis — April 8, 2007 @ 5:17 pm UTC Apr 8,2007
Excellent post!
Comment by Mirjana — October 31, 2007 @ 3:08 pm UTC Oct 31,2007