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 -- > comment to avoid WordPress format issue
;
create index t1_i1 on t1(n1);
begin
dbms_stats.gather_table_stats(
ownname => user,
tabname =>'T1',
cascade => true,
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 two highlighted 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.5538) 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).
Oracle Scratchpad 
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 GMT 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 GMT 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 BST 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 BST 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 BST 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 BST Apr 8,2007 |
Excellent post!
Comment by Mirjana — October 31, 2007 @ 3:08 pm GMT Oct 31,2007 |
Hey Jonathan,
Following up on Adam’s comments and tests, if I understand correctly, AUTOTRACE never prints out the live plan but always a plan from the EXPLAIN PLAN command as opposed to V$SQL_PLAN.
The only way to get the live plan is to TRACE or use v$sql_plan?
Best
Kyle
Comment by Kyle Hailey — September 2, 2009 @ 9:38 pm BST Sep 2,2009 |
Kyle,
That’s correct.
In fact, worst case scenario, you can even be fooled when you run the SQL yourself and check the trace or v$sql_plan. It’s always possible that you (the trouble-shooter) have a different environment from the typical end-user, and it may be an environment change that results in a different execution plan. (e.g. national character set, case insensitive sorting, session level settings for optimizer parameters).
Comment by Jonathan Lewis — September 3, 2009 @ 1:01 pm BST Sep 3,2009 |
It’s clear that the explain plan can vary between the live plan and the explain plan when the analyzing (a DBA for example) session is different from the running session (a user for example) but I was trying to think if an explain plan could be different from the live plan in the same session – all the parameters,settings, grants, schema would be the same so why would the plans differ? There is one reason that you mentioned in CBOF p54 is that EXPLAIN PLAN doesn’t do bind variable peaking and it could also get bind variable data types wrong leading to the wrong plan.
Now I’m curious why AUTOTRACE does all the sampling of data and such instead of just reading the execution stats from v$sql_plan_statistics_all. The stats in $sql_plan_statistics_all are empty unless something like _rowsource_execution_statistics=true, but that would be easy for autotrace to do and this has been possible since 9i.
Kyle Hailey
Comment by Kyle Hailey — September 3, 2009 @ 4:24 pm BST Sep 3,2009 |
Hi Jonathan,
I’m puzzled (as ever!) by the fact that an explain plan is generated from the Optimiser generating the plan from a parse of a statement. Why, or how, can the actual execution plan differ from the one ‘prepared’ by the optimiser?
Surely the optimiser has worked out the best execution plan and that’s what *should* be run, but if not, who or what decided on running a different plan that the optimiser didn’t work out?
Thanks.
Cheers,
Norman.
Comment by Norman Dunbar — September 4, 2009 @ 7:13 am BST Sep 4,2009 |
[…] I’ve turned on some tracing and enabled autotrace. Apart from the extended sql_trace (event 10046 at level 8 ) I’ve also enabled a trace on […]
Pingback by Analytic Agony « Oracle Scratchpad — September 7, 2009 @ 6:23 pm BST Sep 7,2009 |
[…] I’ve published a proof of this special case in response to a comment from Howard Rogers […]
Pingback by Autotrace | Oracle Scratchpad — February 22, 2018 @ 10:34 am GMT Feb 22,2018 |