Striving for Optimal Performance
  • Blog
    • Archive
    • Categories
    • Search
  • Troubleshooting Oracle Performance
    • Description
    • Structure
    • Table of Contents
    • Forewords
    • Reviews
    • Downloadable Files
    • Addenda and Errata
    • First Edition
  • Public Appearances
    • Past Public Appearances
  • Contact
  • About

Execution Plan Hash Value in SQL Trace Files

12 January 2009 4 Comments Written by Christian Antognini

In a previous post I already pointed out that as of 11.1.0.7 new information is provided in the SQL trace files. One of them is the value “plh” in the PARSE, EXEC and FETCH lines. This new value provides the execution plan hash value. While adding this information to the output generated by TVD$XTAT I had to decide how to handle this new value. Hence, I executed the following test case in SQL*Plus…

  • I prepared the test environment by executing the following SQL statements:
ALTER SYSTEM FLUSH SHARED_POOL;

CREATE TABLE t
AS
SELECT rownum AS id, rpad('*',100,'*') AS pad
FROM dual
CONNECT BY level <= 1000;

ALTER TABLE t ADD CONSTRAINT t_pk PRIMARY KEY (id);

EXECUTE dbms_stats.gather_table_stats(ownname=>user,tabname=>'t')

VARIABLE id NUMBER
  • I enabled SQL trace:
EXECUTE dbms_monitor.session_trace_enable(waits=>false,binds=>false)
  • I execute three time the same query that, by the way, takes advantage of extended cursor sharing (a.k.a. adaptive cursor sharing and intelligent cursor sharing):
EXECUTE :id := 10;

SELECT count(pad) FROM t WHERE id < :id;

EXECUTE :id := 990;

SELECT count(pad) FROM t WHERE id < :id;

SELECT count(pad) FROM t WHERE id < :id;
  • I disabled SQL trace and displayed the name of the trace file:
EXECUTE dbms_monitor.session_trace_disable

SELECT value
FROM v$diag_info
WHERE name = 'Default Trace File';

Now, let's check the content of the trace file...

  • For the first query, the following information is provided. Notice that in the line PARSE the value of "plh" is "0"; in the line EXEC the value of "plh" is "4270555908"; in the lines PARSE and EXEC the value of "mis" is "1" (the cursor was hard parsed); according to the execution plan (the line beginning with STAT; notice that I manually removed the runtime statistics and query optimizer estimations to keep the output more readable) the table was read through an index range scan.
PARSING IN CURSOR #2 len=39 dep=0 uid=83 oct=3 lid=83 tim=1231427339018492 hv=1107655156 ad='2e70b9cc' sqlid='asth1mx10aygn'
SELECT count(pad) FROM t WHERE id < :id
END OF STMT
PARSE #2:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1231427339018492
EXEC #2:c=2000,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=4270555908,tim=1231427339018492
FETCH #2:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=4270555908,tim=1231427339018492
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE'
STAT #2 id=2 cnt=9 pid=1 pos=1 obj=72373 op='TABLE ACCESS BY INDEX ROWID T'
STAT #2 id=3 cnt=9 pid=2 pos=1 obj=72374 op='INDEX RANGE SCAN T_PK'
FETCH #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=4270555908,tim=1231427339018492
CLOSE #2:c=0,e=0,dep=0,type=0,tim=1231427339018492
  • For the second query, the following information is provided. Notice that in the lines PARSE and EXEC the value of "plh" is "4270555908" (the same as the previous query) and the value of "mis" is "0" (the cursor was not hard parsed), i.e. a cursor already present in the library cache was reused.
PARSING IN CURSOR #4 len=39 dep=0 uid=83 oct=3 lid=83 tim=1231427339018492 hv=1107655156 ad='2e70b9cc' sqlid='asth1mx10aygn'
SELECT count(pad) FROM t WHERE id < :id
END OF STMT
PARSE #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4270555908,tim=1231427339018492
EXEC #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4270555908,tim=1231427339018492
FETCH #4:c=0,e=0,p=0,cr=19,cu=0,mis=0,r=1,dep=0,og=1,plh=4270555908,tim=1231427339018492
STAT #4 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE'
STAT #4 id=2 cnt=989 pid=1 pos=1 obj=72373 op='TABLE ACCESS BY INDEX ROWID T'
STAT #4 id=3 cnt=989 pid=2 pos=1 obj=72374 op='INDEX RANGE SCAN T_PK'
FETCH #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=4270555908,tim=1231427339018492
CLOSE #4:c=0,e=0,dep=0,type=0,tim=1231427339018492
  • For the third query, the one taking advantage of extended cursor sharing, the following information is provided. Notice that in the line PARSE the value of "plh" is "4270555908" (the same as the previous query) and the value of "mis" is "0" (cursor was not hard parsed); in the line EXEC the value of "plh" is "2966233522" and the value of "mis" is "1" (cursor was hard parsed); according to the execution plan the table was read through a full table scan, i.e. not the same execution plan as the previous queries.
PARSING IN CURSOR #13 len=39 dep=0 uid=83 oct=3 lid=83 tim=1231427339018492 hv=1107655156 ad='2e70b9cc' sqlid='asth1mx10aygn'
SELECT count(pad) FROM t WHERE id < :id
END OF STMT
PARSE #13:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4270555908,tim=1231427339018492
EXEC #13:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2966233522,tim=1231427339018492
FETCH #13:c=0,e=0,p=0,cr=19,cu=0,mis=0,r=1,dep=0,og=1,plh=2966233522,tim=1231427339018492
STAT #13 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE'
STAT #13 id=2 cnt=989 pid=1 pos=1 obj=72373 op='TABLE ACCESS FULL T'
FETCH #13:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2966233522,tim=1231427339018492
CLOSE #13:c=0,e=0,dep=0,type=0,tim=1231427339018492

In summary, according to this test:

  • The value of "plh" in the line EXEC provides the hash value of the execution plan used to execute a SQL statement.
  • The value of "plh" in the line PARSE cannot be trusted.
11gR1, SQL Trace, TVD$XTAT
PerformaSure X-Agent Configuration
11g New Feature in DBMS_MONITOR

4 Comments

  1. Alberto Dell'Era Alberto Dell'Era
    19 January 2009    

    This shows, of course, that the actual compilation of the SQL statement happens during the EXECution, not the PARSing – at least for statements using bind variables :)

    Reply
  2. Milen Kulev Milen Kulev
    25 January 2009    

    Alberto,
    not only the actual compilation, but under some conditions the re-optimization will be postponed to the EXEC phase.
    See ML 199273.1. An excerpt from this ML:
    ”
    . Certain phases may be repositioned dependant on the query submitted. Oracle may combine steps or defer them to a later stage. For example, if bind variable ‘peeking’ is in operation, then the optimizer needs to use the first ‘bound’ value to determine the execution plan for the query. This means that optimization will actually occur in the EXECUTE phase as this is the first time that any bind variable values are available.
    ”

    Best Regards. Milen

    Reply
  3. Alberto Dell'Era Alberto Dell'Era
    26 January 2009    

    Milen,
    sure, I should have been more precise – “compilation” as in “production of the SQL Engine ‘instructions’, i.e. the ‘row source operations’ that together compose ‘the plan’ ” – the “optimization”.

    It was meant as an observation: the reason why the “plh” value of the PARSE line is not reliable is because (at least when bind variables are used) at PARSE time there is no plan associated (or a possibly “old” plan is associated); only at EXEC time the plan is (re)calculated.

    Reply
  4. Kyle Hailey Kyle Hailey
    22 June 2012    

    More nice information – thanks Christian.
    Wish the plan hash was in 10g traces but at least it’s there in 11.

    – Kyle

    Reply

Leave a Reply Cancel reply

Your email address will not be published. Required fields are marked *

This site uses Akismet to reduce spam. Learn how your comment data is processed.