This discussion is archived
10 Replies Latest reply: May 7, 2010 11:31 AM by CharlesHooper RSS

about cost in tkprof

orausern Explorer
Currently Being Moderated
Hi,

How to find what is the cost of a query from tkprof output or from a trace file (got by setting sql_trace=true)? When I set autotrace I get
output which has cost very clearly stated (its output has a column like Cost (%CPU)) Whereas in a raw trace file or even in trprof I dont see the cost. How to see the cost of the query in the tracefile or in the tkprof output?

Thanks,
  • 1. Re: about cost in tkprof
    722368 Explorer
    Currently Being Moderated
    Hi

    run tkprof with explain plan

    $tkprof input_file output_file explain=user/password

    Thanks,
    Siva
  • 2. Re: about cost in tkprof
    CharlesHooper Expert
    Currently Being Moderated
    orausern,

    Oracle Database 11.1.0.6 and higher will output the calculated cost for a line in the execution plan when the STAT lines are written to the 10046 trace file. These STAT lines are then read by TKPROF and output in the "Row Source Operation" section of the output. In the case of 11.1.0.6 and greater, this is the estimated cost for the actual execution plan used by the query. Autotrace shows the estimated cost for what might be the execution plan that will be used by the query (see the blog article http://hoopercharles.wordpress.com/2010/01/11/explain-plan-lies-autotrace-lies-tkprof-lies-what-is-the-plan/). Prior to Oracle Database 11.1.0.6, the calculated, estimated cost was not written to the trace file. The hash value and SQL ID (starting with 11.1.0.6) will be written to the raw 10046 trace file - you can use that information to pull the actual execution plan with cost figures from the library cache along with estimated costs using DBMS_XPLAN.DISPLAY_CURSOR (assuming that you are running Oracle Database 10g R1 or higher). See this three part series for details:
    http://hoopercharles.wordpress.com/2010/01/30/execution-plans-what-is-the-plan-and-where-do-i-find-it/

    The estimated cost figure has a very limited value outside of its intended use by Oracle's query optimizer as a means to derive the individual steps within a specific execution plan. You should not use the estimated cost figures as a means to determine if one query is more efficient than another query.

    Charles Hooper
    Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
    http://hoopercharles.wordpress.com/
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 3. Re: about cost in tkprof
    orausern Explorer
    Currently Being Moderated
    Thanks a lot! I tried the explain= option and now I am getting this error in tkprof output of tracefile:

    error during execute of EXPLAIN PLAN statement
    ORA-00907: missing right parenthesis

    I googled and saw a referene to metalink note and also created the plan table and yet getting same error...Any suggestions on it?

    Thanks,
  • 4. Re: about cost in tkprof
    damorgan Oracle ACE Director
    Currently Being Moderated
    so far you have not posted a version number
    SELECT * FROM v$version;
    or cut-and-pasted anything we can look at. This would be a good time to fill in the blanks. We can not help you with what we can not see.
  • 5. Re: about cost in tkprof
    orausern Explorer
    Currently Being Moderated
    Sorry, here it is:
    Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bi
    PL/SQL Release 10.2.0.4.0 - Production
    CORE 10.2.0.4.0 Production
    TNS for Solaris: Version 10.2.0.4.0 - Production
    NLSRTL Version 10.2.0.4.0 - Production
  • 6. Re: about cost in tkprof
    722368 Explorer
    Currently Being Moderated
    Hi,

    It should work. the syntax is follows:

    tkprof filename1 filename2 [waits=yes|no] [sort=option] [print=n]
    [aggregate=yes|no] [insert=filename3] [sys=yes|no] [table=schema.table]
    [explain=user/password] [record=filename4] [width=n]

    refer http://www.ordba.net/Tutorials/OracleUtilities~TKPROF.htm

    Thanks,
    siva
  • 7. Re: about cost in tkprof
    orausern Explorer
    Currently Being Moderated
    There is something I am missing but I dont know what...I created a plan table in that schema using utlxplan I am giving schemaname.tablename in the tkprof and yet it keeps giving me same error!
  • 8. Re: about cost in tkprof
    CharlesHooper Expert
    Currently Being Moderated
    orausern wrote:
    Thanks a lot! I tried the explain= option and now I am getting this error in tkprof output of tracefile:

    error during execute of EXPLAIN PLAN statement
    ORA-00907: missing right parenthesis

    I googled and saw a referene to metalink note and also created the plan table and yet getting same error...Any suggestions on it?

    Thanks,
    There is a reason why I did not suggest using the EXPLAIN parameter of TKPROF. The main reason is that it may show a very different execution plan. Secondly, it apparently does not include any COST values for Oracle 10.2.0.x. Third, I recommended against using the calculated cost values for comparisons. A demonstration is necessary:
    CREATE TABLE T1(
      C1 NUMBER,
      C2 VARCHAR2(255),
      PRIMARY KEY (C1));
     
    CREATE TABLE T2(
      C1 NUMBER,
      C2 VARCHAR2(255),
      PRIMARY KEY (C1));
     
    INSERT INTO
      T1
    SELECT
      ROWNUM,
      LPAD('A',255,'A')
    FROM
      (SELECT
        ROWNUM RN
      FROM
        DUAL
      CONNECT BY
        LEVEL<=10000) V1,
      (SELECT
        ROWNUM RN
      FROM
        DUAL
      CONNECT BY
        LEVEL<=30) V2;
     
    INSERT INTO
      T2
    SELECT
      ROWNUM,
      LPAD('A',255,'A')
    FROM
      (SELECT
        ROWNUM RN
      FROM
        DUAL
      CONNECT BY
        LEVEL<=10000) V1,
      (SELECT
        ROWNUM RN
      FROM
        DUAL
      CONNECT BY
        LEVEL<=30) V2;
     
    COMMIT;
     
    EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE)
    EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T2',CASCADE=>TRUE)
    We now have two tables, each with 300,000 rows - each of the tables has a primary key index. The test case continues:
    VARIABLE N1 NUMBER
    VARIABLE N2 NUMBER
     
    EXEC :N1:=1
    EXEC :N2:=100000
     
    SET AUTOTRACE TRACEONLY STATISTICS
     
    ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 4';
    ALTER SESSION SET TRACEFILE_IDENTIFIER = 'EXPLAIN_PLAN_TEST';
     
    SELECT
      T1.C1,
      T2.C1,
      SUBSTR(T1.C2,1,1) T1_C2,
      SUBSTR(T2.C2,1,1) T2_C2
    FROM
      T1,
      T2
    WHERE
      T1.C1=T2.C1
      AND T1.C1 BETWEEN :N1 AND :N2;
     
    EXEC :N2:=10
     
    SELECT
      T1.C1,
      T2.C1,
      SUBSTR(T1.C2,1,1) T1_C2,
      SUBSTR(T2.C2,1,1) T2_C2
    FROM
      T1,
      T2
    WHERE
      T1.C1=T2.C1
      AND T1.C1 BETWEEN :N1 AND :N2;
     
    ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
    The output of the above is the following:
    100000 rows selected.
     
    Statistics
    ---------------------------------------------------
          45  recursive calls
           0  db block gets
       24673  consistent gets
       26419  physical reads
           0  redo size
     2051555  bytes sent via SQL*Net to client
       73660  bytes received via SQL*Net from client
        6668  SQL*Net roundtrips to/from client
           0  sorts (memory)
           0  sorts (disk)
      100000  rows processed
      
    10 rows selected.
     
    Statistics
    ---------------------------------------------------
         0  recursive calls
         0  db block gets
     22257  consistent gets
     20896  physical reads
         0  redo size
       605  bytes sent via SQL*Net to client
       334  bytes received via SQL*Net from client
         2  SQL*Net roundtrips to/from client
         0  sorts (memory)
         0  sorts (disk)
        10  rows processed
    Now we have a 10046 trace file, move it back to the client PC, and then continue.
    exit
     
    TKPROF test_ora_2392_explain_plan_test.trc test_ora_2392_explain_plan_test.txt EXPLAIN=testuser/testpass@test
    So, what does the resulting TKPROF summary file show?
    SELECT
      T1.C1,
      T2.C1,
      SUBSTR(T1.C2,1,1) T1_C2,
      SUBSTR(T2.C2,1,1) T2_C2
    FROM
      T1,
      T2
    WHERE
      T1.C1=T2.C1
      AND T1.C1 BETWEEN :N1 AND :N2
     
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        2      0.00       0.00          0          0          0           0
    Execute      2      0.00       0.00          0          0          0           0
    Fetch     6670      2.06       3.09      47315      46930          0      100010
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total     6674      2.06       3.09      47315      46930          0      100010
     
    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 31  (TESTUSER)
     
    Rows     Row Source Operation
    -------  ---------------------------------------------------
     100000  FILTER  (cr=24673 pr=26419 pw=5239 time=41377235 us)
     100000   HASH JOIN  (cr=24673 pr=26419 pw=5239 time=41177148 us)
     100000    TABLE ACCESS FULL T1 (cr=11128 pr=11113 pw=0 time=495 us)
     100000    TABLE ACCESS FULL T2 (cr=13545 pr=10067 pw=0 time=100493 us)
     
    Rows     Execution Plan
    -------  ---------------------------------------------------
          0  SELECT STATEMENT   MODE: ALL_ROWS
     100000   FILTER
     100000    HASH JOIN
     100000     TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF 'T1' (TABLE)
     100000      INDEX   MODE: ANALYZED (RANGE SCAN) OF 'SYS_C0020592' (INDEX (UNIQUE))
          0     TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF 'T2' (TABLE)
          0      INDEX   MODE: ANALYZED (RANGE SCAN) OF 'SYS_C0020593' (INDEX (UNIQUE))
    Hopefully, the above helps you understand why I did not suggest the use of the EXPLAIN parameter.

    Charles Hooper
    Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
    http://hoopercharles.wordpress.com/
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 9. Re: about cost in tkprof
    orausern Explorer
    Currently Being Moderated
    Hi Charles,

    It is my ignorance that I can't decipher all the details you have shared...actually also some work pressure...I can put a more generic question like this :
    when I need to report cost of a poorly performing query, I ran autotrace traceonly explain and got the data of cost and the data of execution plan...but I have also read that - sql trace file and tkprof give better data than auto trace...my problem was: instead of trying to get query cost from the autotrace , i am searching for query cost in tkprof or tracefile and I dont' see it there...now given two options which is more reliable (lets assume the choice is only between the two, not some other option), than what should be more reliable in a fairly important situation?

    Thanks again!!
  • 10. Re: about cost in tkprof
    CharlesHooper Expert
    Currently Being Moderated
    orausern wrote:
    Hi Charles,

    It is my ignorance that I can't decipher all the details you have shared...actually also some work pressure...I can put a more generic question like this :
    when I need to report cost of a poorly performing query, I ran autotrace traceonly explain and got the data of cost and the data of execution plan...but I have also read that - sql trace file and tkprof give better data than auto trace...my problem was: instead of trying to get query cost from the autotrace , i am searching for query cost in tkprof or tracefile and I dont' see it there...now given two options which is more reliable (lets assume the choice is only between the two, not some other option), than what should be more reliable in a fairly important situation?

    Thanks again!!
    The calculated cost may be very misleading. There are a large number of factors that are considered when the costs are derived, and some of those factors may mislead the optimizer into either understating the true cost to the end user (typically considered to be execution time) or overstating the true cost to the end user. To the query optimizer, cost is supposed to represent time, but as I stated, you should NOT compare the calculated cost of one query with the calculated cost for another query.

    It would probably be beneficial for you to experiment with a couple of things:
    * 10046 trace at either level 8 or 12
    * SET TIMING ON in SQL*Plus
    * DBMS_XPLAN.DISPLAY_CURSOR

    Ignore the costs.

    For fun, here is another test script, using the same tables that were created in my previous response:
    VARIABLE N1 NUMBER
    VARIABLE N2 NUMBER
     
    EXEC :N1:=1
    EXEC :N2:=100000
     
    SET TIMING ON
    SET AUTOTRACE TRACEONLY STATISTICS EXPLAIN
    SET PAGESIZE 1000
    SET LINESIZE 140
     
    ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';
    ALTER SESSION SET TRACEFILE_IDENTIFIER = 'EXPLAIN_PLAN_TEST2';
     
    SELECT
      T1.C1,   T2.C1,
      SUBSTR(T1.C2,1,1) T1_C2,
      SUBSTR(T2.C2,1,1) T2_C2
    FROM
      T1,
      T2
    WHERE
      T1.C1=T2.C1
      AND T1.C1 BETWEEN :N1 AND :N2;
     
    EXEC :N2:=10
     
    SELECT
      T1.C1,   T2.C1,
      SUBSTR(T1.C2,1,1) T1_C2,
      SUBSTR(T2.C2,1,1) T2_C2
    FROM
      T1,
      T2
    WHERE
      T1.C1=T2.C1
      AND T1.C1 BETWEEN :N1 AND :N2; 
     
    SELECT SYSDATE FROM DUAL;
      
    ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
    I actually executed the script a couple of times, changing the TRACEFILE_IDENTIFIER each time, because the first execution would require a hard parse and would likely require more physical reads - I wanted to factor those out of the run time. The following was displayed when the script ran:
    100000 rows selected.
     
    Elapsed: 00:00:03.82
     
    Execution Plan
    ----------------------------------------------------------
    Plan hash value: 77308553
     
    ----------------------------------------------------------------------------------------------
    | Id  | Operation                     | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
    ----------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT              |              |   749 |   380K|   111   (1)| 00:00:01 |
    |*  1 |  FILTER                       |              |       |       |            |          |
    |*  2 |   HASH JOIN                   |              |   749 |   380K|   111   (1)| 00:00:01 |
    |   3 |    TABLE ACCESS BY INDEX ROWID| T1           |   750 |   190K|    55   (0)| 00:00:01 |
    |*  4 |     INDEX RANGE SCAN          | SYS_C0020592 |  1350 |       |     4   (0)| 00:00:01 |
    |   5 |    TABLE ACCESS BY INDEX ROWID| T2           |   750 |   190K|    55   (0)| 00:00:01 |
    |*  6 |     INDEX RANGE SCAN          | SYS_C0020593 |  1350 |       |     4   (0)| 00:00:01 |
    ----------------------------------------------------------------------------------------------
     
    Predicate Information (identified by operation id):
    ---------------------------------------------------
       1 - filter(TO_NUMBER(:N1)<=TO_NUMBER(:N2))
       2 - access("T1"."C1"="T2"."C1")
       4 - access("T1"."C1">=TO_NUMBER(:N1) AND "T1"."C1"<=TO_NUMBER(:N2))
       6 - access("T2"."C1">=TO_NUMBER(:N1) AND "T2"."C1"<=TO_NUMBER(:N2))
     
    Statistics
    ------------------------------------------------
          0  recursive calls
          0  db block gets
      28923  consistent gets
      21711  physical reads
          0  redo size
    2051555  bytes sent via SQL*Net to client
      73660  bytes received via SQL*Net from client
       6668  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
     100000  rows processed
      
    10 rows selected.
     
    Elapsed: 00:00:01.04
     
    Execution Plan
    ----------------------------------------------------------
    Plan hash value: 77308553
     
    ----------------------------------------------------------------------------------------------
    | Id  | Operation                     | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
    ----------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT              |              |   749 |   380K|   111   (1)| 00:00:01 |
    |*  1 |  FILTER                       |              |       |       |            |          |
    |*  2 |   HASH JOIN                   |              |   749 |   380K|   111   (1)| 00:00:01 |
    |   3 |    TABLE ACCESS BY INDEX ROWID| T1           |   750 |   190K|    55   (0)| 00:00:01 |
    |*  4 |     INDEX RANGE SCAN          | SYS_C0020592 |  1350 |       |     4   (0)| 00:00:01 |
    |   5 |    TABLE ACCESS BY INDEX ROWID| T2           |   750 |   190K|    55   (0)| 00:00:01 |
    |*  6 |     INDEX RANGE SCAN          | SYS_C0020593 |  1350 |       |     4   (0)| 00:00:01 |
    ----------------------------------------------------------------------------------------------
     
    Predicate Information (identified by operation id):
    ---------------------------------------------------
       1 - filter(TO_NUMBER(:N1)<=TO_NUMBER(:N2))
       2 - access("T1"."C1"="T2"."C1")
       4 - access("T1"."C1">=TO_NUMBER(:N1) AND "T1"."C1"<=TO_NUMBER(:N2))
       6 - access("T2"."C1">=TO_NUMBER(:N1) AND "T2"."C1"<=TO_NUMBER(:N2))
     
    Statistics
    ---------------------------------------------
        0  recursive calls
        0  db block gets
    22257  consistent gets
    21716  physical reads
        0  redo size
      605  bytes sent via SQL*Net to client
      334  bytes received via SQL*Net from client
        2  SQL*Net roundtrips to/from client
        0  sorts (memory)
        0  sorts (disk)
       10  rows processed
    In the above, notice that the first execution required 3.82 seconds, and had a calculated cost of 111. The second execution required 1.04 seconds, and also had a calculated cost of 111. Note also that the displayed execution plan is incorrect. The elapsed time was output automatically because the script included SET TIMING ON. Keep in mind the effects of the buffer cache - the first time a SQL statement is executed, it will probably take longer to execute than it does on the second execution, and that is the reason why I executed the SQL statement a couple of extra times before I started looking at the performance. The above statistics indicate that 21,711 physical block reads were performed and 28,923 consistent gets on the first execution. On the second execution the number of physical block reads increased to 21,716 while the number of consistent gets decreased to 22,257.

    If we run the 10046 trace file through TKPROF:
    TKPROF test_ora_1608_explain_plan_test2.trc test_ora_1608_explain_plan_test2.txt
    We now see the following in the resulting output:
    SELECT
      T1.C1,   T2.C1,
      SUBSTR(T1.C2,1,1) T1_C2,
      SUBSTR(T2.C2,1,1) T2_C2
    FROM
      T1,
      T2
    WHERE
      T1.C1=T2.C1
      AND T1.C1 BETWEEN :N1 AND :N2
     
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        2      0.00       0.00          0          0          0           0
    Execute      2      0.00       0.00          0          0          0           0
    Fetch     6670      2.35       2.60      43427      51180          0      100010
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total     6674      2.35       2.60      43427      51180          0      100010
     
    Misses in library cache during parse: 0
    Optimizer mode: ALL_ROWS
    Parsing user id: 31  
     
    Rows     Row Source Operation
    -------  ---------------------------------------------------
     100000  FILTER  (cr=28923 pr=21711 pw=0 time=1299979 us)
     100000   HASH JOIN  (cr=28923 pr=21711 pw=0 time=1199904 us)
     100000    TABLE ACCESS FULL T1 (cr=11128 pr=11028 pw=0 time=596 us)
     100000    TABLE ACCESS FULL T2 (cr=17795 pr=10683 pw=0 time=100562 us)
     
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                    6670        0.00          0.00
      db file scattered read                        436        0.01          0.97
      db file sequential read                       755        0.00          0.05
      SQL*Net message from client                  6670        0.01          1.86
    The wait events are critical to the understanding of why the query required as long as it did to execute.

    Now, let's jump into the 10046 raw trace file. We see the following:
    PARSING IN CURSOR #6 len=145 dep=0 uid=31 oct=3 lid=31 tim=3828906982 hv=631402459 ad='a68ddf18'
    SELECT
      T1.C1,   T2.C1,
      SUBSTR(T1.C2,1,1) T1_C2,
      SUBSTR(T2.C2,1,1) T2_C2
    FROM
      T1,
      T2
    WHERE
      T1.C1=T2.C1
      AND T1.C1 BETWEEN :N1 AND :N2
    END OF STMT
    PARSE #6:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=3828906975
    BINDS #6:
    kkscoacd
     Bind#0
      oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
      oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0
      kxsbbbfp=13cb6528  bln=22  avl=02  flg=05
      value=1
     Bind#1
      oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
      oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=24
      kxsbbbfp=13cb6540  bln=22  avl=02  flg=01
      value=100000
    ...
    STAT #6 id=1 cnt=100000 pid=0 pos=1 obj=0 op='FILTER  (cr=28923 pr=21711 pw=0 time=1299979 us)'
    STAT #6 id=2 cnt=100000 pid=1 pos=1 obj=0 op='HASH JOIN  (cr=28923 pr=21711 pw=0 time=1199904 us)'
    STAT #6 id=3 cnt=100000 pid=2 pos=1 obj=114319 op='TABLE ACCESS FULL T1 (cr=11128 pr=11028 pw=0 time=596 us)'
    STAT #6 id=4 cnt=100000 pid=2 pos=2 obj=114321 op='TABLE ACCESS FULL T2 (cr=17795 pr=10683 pw=0 time=100562 us)'
    There is the hash value: hv=631402459

    Now, back in SQL*Plus, we can do the following:
    SET AUTOTRACE OFF
     
    SELECT
      SQL_ID
    FROM
      V$SQL
    WHERE
      HASH_VALUE=631402459;
     
    SQL_ID
    -------------
    5pf2mzwku4vyv
    There is the SQL_ID that we need to pull the actual execution plan from the library cache. If we integrate that SQL statement into another than pulls back the actual execution plan, this is what we see:
    SELECT
      *
    FROM
      TABLE(DBMS_XPLAN.DISPLAY_CURSOR(
        (SELECT
          SQL_ID
        FROM
          V$SQL
        WHERE
          HASH_VALUE=631402459),
        NULL,
        'TYPICAL +PEEKED_BINDS'));
     
    SQL_ID  5pf2mzwku4vyv, child number 0
    -------------------------------------
    SELECT   T1.C1,   T2.C1,   SUBSTR(T1.C2,1,1) T1_C2,   SUBSTR(T2.C2,1,1)
    T2_C2 FROM   T1,   T2 WHERE   T1.C1=T2.C1   AND T1.C1 BETWEEN :N1 AND :N2
     
    Plan hash value: 487071653
     
    ------------------------------------------------------------------------------------
    | Id  | Operation           | Name | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
    ------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT    |      |       |       |       |  1809 (100)|          |
    |*  1 |  FILTER             |      |       |       |       |            |          |
    |*  2 |   HASH JOIN         |      |   100K|    49M|    25M|  1809   (4)| 00:00:09 |
    |*  3 |    TABLE ACCESS FULL| T1   |   100K|    24M|       |   568   (5)| 00:00:03 |
    |*  4 |    TABLE ACCESS FULL| T2   |   100K|    24M|       |   568   (5)| 00:00:03 |
    ------------------------------------------------------------------------------------
     
    Peeked Binds (identified by position):
    --------------------------------------
       1 - :N1 (NUMBER): 1
       2 - :N2 (NUMBER): 100000
     
    Predicate Information (identified by operation id):
    ---------------------------------------------------
       1 - filter(:N1<=:N2)
       2 - access("T1"."C1"="T2"."C1")
       3 - filter(("T1"."C1"<=:N2 AND "T1"."C1">=:N1))
       4 - filter(("T2"."C1"<=:N2 AND "T2"."C1">=:N1))
    So, the above shows the calculated cost (1809) for the actual execution plan used for the query when it was executed and the peeked bind variables that were submitted during the hard parse.

    The next example changes the STATISTICS_LEVEL at the session level to ALL, which has a tendency to increase the execution time for queries (a hint can be added to the query so that changing the STATISTICS_LEVEL is not necessary):
    VARIABLE N1 NUMBER
    VARIABLE N2 NUMBER
      
    EXEC :N1:=1
    EXEC :N2:=100000
     
    ALTER SESSION SET STATISTICS_LEVEL='ALL'; 
     
    SELECT
      T1.C1,   T2.C1,
      SUBSTR(T1.C2,1,1) T1_C2,
      SUBSTR(T2.C2,1,1) T2_C2
    FROM
      T1,
      T2
    WHERE
      T1.C1=T2.C1
      AND T1.C1 BETWEEN :N1 AND :N2;
    OK, let's see the execution plan for the query that was just executed:
    SELECT
      *
    FROM
      TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +PROJECTION +ALIAS +PREDICATE +COST +BYTES'));
     
    Plan hash value: 487071653
     
    -------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    | Id  | Operation           | Name | Starts | E-Rows |E-Bytes|E-Temp | Cost (%CPU)| A-Rows |   A-Time   | Buffers | Reads  | Writes |  OMem|  1Mem | Used-Mem | Used-Tmp|
    -------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    |*  1 |  FILTER             |      |      1 |        |       |       |            |    100K|00:00:04.56 |   23056 |  27980 |   6231 |      |       |          |         |
    |*  2 |   HASH JOIN         |      |      1 |    100K|    49M|    25M|  1809   (4)|    100K|00:00:04.45 |   23056 |  27980 |   6231 |   29M|  3792K|   11M (1)|   52224 |
    |*  3 |    TABLE ACCESS FULL| T1   |      1 |    100K|    24M|       |   568   (5)|    100K|00:00:01.99 |   11128 |  11054 |      0 |      |       |          |         |
    |*  4 |    TABLE ACCESS FULL| T2   |      1 |    100K|    24M|       |   568   (5)|    100K|00:00:01.51 |   11928 |  10695 |      0 |      |       |          |         |
    -------------------------------------------------------------------------------------------------------------------------------------------------------------------------
     
    Query Block Name / Object Alias (identified by operation id):
    -------------------------------------------------------------
       1 - SEL$1
       3 - SEL$1 / T1@SEL$1
       4 - SEL$1 / T2@SEL$1
     
    Peeked Binds (identified by position):
    --------------------------------------
       1 - (NUMBER): 1
       2 - (NUMBER): 100000
     
    Predicate Information (identified by operation id):
    ---------------------------------------------------
       1 - filter(:N1<=:N2)
       2 - access("T1"."C1"="T2"."C1")
       3 - filter(("T1"."C1"<=:N2 AND "T1"."C1">=:N1))
       4 - filter(("T2"."C1"<=:N2 AND "T2"."C1">=:N1))
     
    Column Projection Information (identified by operation id):
    -----------------------------------------------------------
       1 - "T1"."C1"[NUMBER,22], "T2"."C1"[NUMBER,22], "T1"."C2"[VARCHAR2,255], "T2"."C2"[VARCHAR2,255]
       2 - (#keys=1) "T1"."C1"[NUMBER,22], "T2"."C1"[NUMBER,22], "T1"."C2"[VARCHAR2,255], "T2"."C2"[VARCHAR2,255]
       3 - "T1"."C1"[NUMBER,22], "T1"."C2"[VARCHAR2,255]
       4 - "T2"."C1"[NUMBER,22], "T2"."C2"[VARCHAR2,255]
    The above shows the estimated costs as well as the actual execution statistics.

    My blog has a number of related articles. For example, this one on DBMS_XPLAN:
    http://hoopercharles.wordpress.com/2010/03/01/dbms_xplan-format-parameters/

    Charles Hooper
    Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
    http://hoopercharles.wordpress.com/
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points