10 Replies Latest reply: May 7, 2010 11:31 AM by Charles Hooper RSS

    about cost in tkprof

    orausern
      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
          Hi

          run tkprof with explain plan

          $tkprof input_file output_file explain=user/password

          Thanks,
          Siva
          • 2. Re: about cost in tkprof
            Charles Hooper
            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
              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
                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
                  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
                    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
                      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
                        Charles Hooper
                        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
                          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
                            Charles Hooper
                            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.