Oracle Scratchpad

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.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).

13 Comments »

  1. 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 GMT Nov 30,2006 | Reply

  2. 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 | Reply

  3. 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 | Reply

  4. 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 GMT Apr 8,2007 | Reply

  5. 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 GMT Apr 8,2007 | Reply

  6. How do I get autotrace to show me the parent Id column in 10gr2?

    Comment by prichard — April 8, 2007 @ 4:32 pm GMT Apr 8,2007 | Reply

  7. 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 GMT Apr 8,2007 | Reply

  8. Excellent post!

    Comment by Mirjana — October 31, 2007 @ 3:08 pm GMT Oct 31,2007 | Reply

  9. 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 GMT Sep 2,2009 | Reply

  10. 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 GMT Sep 3,2009 | Reply

  11. 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 GMT Sep 3,2009 | Reply

  12. 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 GMT Sep 4,2009 | Reply

  13. [...] 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 GMT Sep 7,2009 | Reply


RSS feed for comments on this post. TrackBack URI

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

Theme: Rubric. Get a free blog at WordPress.com

Follow

Get every new post delivered to your Inbox.

Join 4,422 other followers