This discussion is archived
1 2 Previous Next 24 Replies Latest reply: Jan 30, 2012 6:19 AM by 905989 RSS

Tkprof output question

905989 Newbie
Currently Being Moderated
Hello,

The following is a report from TKPROF that I have generated. Oracle 11.2.0, 8K block size
 
SELECT *
FROM
 T WHERE OBJECT_ID = :B1


call     count       cpu    elapsed       disk      query    current        rows

------- ------  -------- ---------- ---------- ---------- ----------  ----------

Parse        1      0.01       0.00          1         63          0           0

Execute  72181      0.73       1.02          4         54          0           0

Fetch    72181      1.58      10.08      81365     368648          0       71726

------- ------  -------- ---------- ---------- ---------- ----------  ----------

total   144363      2.33      11.12      81370     368765          0       71726


Misses in library cache during parse: 1

Optimizer mode: ALL_ROWS

Parsing user id: 96  (USER)   (recursive depth: 1)


Rows     Row Source Operation

-------  ---------------------------------------------------

      1  TABLE ACCESS BY INDEX ROWID T (cr=5 pr=11 pw=0 time=0 us cost=4 size=8092 card=1)

      1   INDEX UNIQUE SCAN T_PK (cr=3 pr=6 pw=0 time=0 us cost=2 size=0 card=1)(object id 83084)

Rows     Execution Plan

-------  ---------------------------------------------------

      0  SELECT STATEMENT   MODE: ALL_ROWS

      1   TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF 'T' (TABLE)

  

      1    INDEX   MODE: ANALYZED (UNIQUE SCAN) OF 'T_PK' (INDEX

               (UNIQUE))

  

  

Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total Waited

  ----------------------------------------   Waited  ----------  ------------

  Disk file operations I/O                        3        0.00          0.00

  db file sequential read                     12464        0.00          2.78

  db file scattered read                      14590        0.00          4.67

********************************************************************************
So I see this query read 81370 physical blocks in 2.33 seconds CPU time and 11.12 seconds elapsed .

In below:
Rows     Row Source Operation

-------  ---------------------------------------------------

      1  TABLE ACCESS BY INDEX ROWID T (cr=5 pr=11 pw=0 time=0 us cost=4 size=8092 card=1)

      1   INDEX UNIQUE SCAN T_PK (cr=3 pr=6 pw=0 time=0 us cost=2 size=0 card=1)(object id 83084)
Does it mean there were a total of pr=11 physical IO including 6 Physical IO for index?

Also the wait times 2.78+4.67 = 7.45 seconds. This should roughly equal to 11.12 – 2.33 = 8.79. Are there other waits that have not been accounted for in elapsed time?

Thanks

Edited by: 902986 on 25-Jan-2012 04:26
  • 1. Re: Tkprof output question
    912595 Expert
    Currently Being Moderated
    Hi,

    First you need to check the reson for
    "Misses in library cache during parse: 1" I believe this is the first time you are running the query in database. But if you are getting the in all execution then you need to investigate this.

    Rows Row Source Operation
    ------- ---------------------------------------------------
    1 TABLE ACCESS BY INDEX ROWID T (cr=5 pr=11 pw=0 time=0 us cost=4 size=8092 card=1)
    1 INDEX UNIQUE SCAN T_PK (cr=3 pr=6 pw=0 time=0 us cost=2 size=0 card=1)(object id 83084)


    Now to the point above, You have INDEX UNIQUE SCAN, so this means for every single index value exactly one value is returned from table. So while aceesing index it read total of 6 and while accessing tables it read 11.
    And 11 doesn;t includes the physical read of index.

    Regards

    Edited by: 909592 on Jan 25, 2012 6:09 PM

    Edited by: 909592 on Jan 25, 2012 6:09 PM
  • 2. Re: Tkprof output question
    905989 Newbie
    Currently Being Moderated
    thanks a lot.

    I ran the query after reboot (first time) so the miss in library cache is correct.

    When I look at wait time I notice almost equal scattered and sequential reads. I think the sequential reads are single block index read. How about the scattered reads are they multi-block data reads or multi-block indexd reads?

    regards
  • 3. Re: Tkprof output question
    912595 Expert
    Currently Being Moderated
    Hi ,

    In simple words thats because - You have index unique scan and for every single key vale accessed there is single row accessed from table.
    In unique scan scattered read and sequenctial reads are alomost equal.

    Regards
  • 4. Re: Tkprof output question
    Nikolay Savvinov Guru
    Currently Being Moderated
    Hi,

    execution plan has a hierarchical structure, and parents I/O, cost, timing etc. is a sum of corresponding metrics for all its children plus the metrics of the operation itself. E.g. the cost of a HASH JOIN is the cost of obtaining its inputs plus the additional costs of combining them.

    For index scans, there may be one or two steps involved: either Oracle scans the index blocks and finds all it needs there, or it may additionally need to visit the table block (using the rowid found in the index) to satisfy the query. In the latter case, the operation will be TABLE ACCESS BY ROWID with one child, INDEX RANGE(UNIQUE, SKIP etc.) SCAN, and its cost (I/O etc.) will be the sum of the cost of visiting index blocks (the child operation) and visiting the table blocks using the rowids (the parent operation).



    Best regards,
    Nikolay

    Edited by: Nikolay Savvinov on Jan 25, 2012 6:47 AM
  • 5. Re: Tkprof output question
    905989 Newbie
    Currently Being Moderated
    Thanks

    In this case there is no index covering and it finds the record using the primary key and reads the record from the table in

    So in below
    Rows     Row Source Operation
     
    -------  ---------------------------------------------------
     
          1  TABLE ACCESS BY INDEX ROWID T (cr=5 pr=11 pw=0 time=0 us cost=4 size=8092 card=1)
     
          1   INDEX UNIQUE SCAN T_PK (cr=3 pr=6 pw=0 time=0 us cost=2 size=0 card=1)(object id 83084)
     
    Rows     Execution Plan
     
    -------  ---------------------------------------------------
     
          0  SELECT STATEMENT   MODE: ALL_ROWS
     
          1   TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF 'T' (TABLE)
          1    INDEX   MODE: ANALYZED (UNIQUE SCAN) OF 'T_PK' (INDEX
     
                   (UNIQUE))
     
    Does that PIO of 11 in parent (table) include 6 PIO from the index (child) then?

    regards
  • 6. Re: Tkprof output question
    912595 Expert
    Currently Being Moderated
    "Oracle enforces UNIQUE integrity constraints by automatically defining a unique index on the unique key."
    Thats the reason you are having index access
  • 7. Re: Tkprof output question
    905989 Newbie
    Currently Being Moderated
    Yes sure I realize that.

    Does that PIO of 11 in parent (table) include 6 PIO from the index (child) then?

    thanks
  • 8. Re: Tkprof output question
    912595 Expert
    Currently Being Moderated
    Hi,

    11 is for Table and 6 is for index. So its doesn't include for index.

    Regards
  • 9. Re: Tkprof output question
    CharlesHooper Expert
    Currently Being Moderated
    902986 wrote:
    Yes sure I realize that.

    Does that PIO of 11 in parent (table) include 6 PIO from the index (child) then?

    thanks
    Please read again what Nikolay Savvinov stated:
    "execution plan has a hierarchical structure, and parents I/O, cost, timing etc. is a sum of corresponding metrics for all its children plus the metrics of the operation itself. E.g. the cost of a HASH JOIN is the cost of obtaining its inputs plus the additional costs of combining them."

    Your Row Source Operation execution plan shows:
    Rows     Row Source Operation
    -------  --------------------------------------------------- 
          1  TABLE ACCESS BY INDEX ROWID T (cr=5 pr=11 pw=0 time=0 us cost=4 size=8092 card=1)
          1   INDEX UNIQUE SCAN T_PK (cr=3 pr=6 pw=0 time=0 us cost=2 size=0 card=1)(object id 83084)
    In the above, the "TABLE ACCESS BY INDEX ROWID" operation is the parent operation and the "INDEX UNIQUE SCAN" is the child operation. The child's statistics are rolled into the parent's statistics. In Oracle Database 11.1 and above, the default behavior is to output the STAT lines (that is the Row Source Operation execution plan) after the first execution of the SQL statement. For the first execution of the SQL statement, there were 11 physical block reads, 6 from the index and 5 from the table. There were 5 consistent gets, 3 from the index and 2 from the table. The estimated cost for the index access is 2, and the estimated cost for just the table access is 2.

    I see that you also used the EXPLAIN option of TKPROF - that can lead to misleading execution plans being written to the TKPROF output, especially when bind variables are involved. The 1 parse call should be expected - it would be bad if there were 72,181 parses, because that would mean that there would be 1 parse per execution - a sign that the cursor was not held open either by the application or by the session cursor cache. Simply enabling a 10046 trace in a session changes the environment for the session, which will typically require a hard parse of previously parsed SQL statements when those SQL statements are re-executed. Note that "recursive depth: 1" appears in the output, which suggests that this SQL statement is found in a PL/SQL block.

    db file scattered read waits indicate that more than 1 block is read from disk at a time. You can refer to the raw 10046 trace file to determine how many blocks are read on average in the db file scattered read waits.

    Charles Hooper
  • 10. Re: Tkprof output question
    905989 Newbie
    Currently Being Moderated
    thank you

    I used the following to create the output file
    tkprof=<trace_file> <out_file> sys=no explain=user/password table=user.plan_table
    
    Your suggestion is 
    
    tkprof=<trace_file> <out_file> sys=no table=user.plan_table
    Is that what you are suggesting?

    thanks
  • 11. Re: Tkprof output question
    Nikolay Savvinov Guru
    Currently Being Moderated
    Hi,

    the short answer is -- yes, it does.

    When in doubt, you can make a simple test case to get a better feel how things work in Oracle, e.g. create a simple table with two columns and an index on one of them, and then compare plans for a statement returning one and both columns, and their costs (I/O etc.):

    DROP TABLE T;

    CREATE TABLE T
    AS SELECT LEVEL X, LEVEL Y
    FROM DUAL
    CONNECT BY LEVEL <= 1E5;

    CREATE INDEX I$T$X ON T(X);

    EXEC DBMS_STATS.GATHER_TABLE_STATS('SCOTT', 'T');

    ALTER SESSION SET STATISTICS_LEVEL = ALL;

    SELECT X, Y from T WHERE x = 5;

    SELECT X from T where x=5;

    then you can do the tracing (or simply examine rowsource stats using dbms_xplan.display_cursor) and see what the difference is and where it is coming from.

    Best regards,
    Nikolay
  • 12. Re: Tkprof output question
    Nikolay Savvinov Guru
    Currently Being Moderated
    Hi all,

    I spotted a rather confusing typo in one of my posts in the tread, some => sum, it may be responsible for some of the misunderstanding here. I've corrected it now.

    Best regards,
    Nikolay
  • 13. Re: Tkprof output question
    CharlesHooper Expert
    Currently Being Moderated
    902986 wrote:
    thank you

    I used the following to create the output file
    tkprof=<trace_file> <out_file> sys=no explain=user/password table=user.plan_table
    
    Your suggestion is 
    
    tkprof=<trace_file> <out_file> sys=no table=user.plan_table
    Is that what you are suggesting?

    thanks
    I suggest just trying:
     tkprof=<trace_file> <out_file>
    The missing elapsed time might be found by looking at the dep=2, dep=3, etc. SQL statements.

    For anyone who wishes to confirm what I stated about the parent-child relationships of the statistics, here is a simple test case script:
    CREATE TABLE T3 (
      C1 NUMBER,
      C2 VARCHAR2(300),
      PRIMARY KEY(C1));
     
    INSERT INTO
      T3
    SELECT
      ROWNUM C1,
      RPAD('A',300,'A')
    FROM
      DUAL
    CONNECT BY
      LEVEL<=200;
     
    COMMIT;
     
    EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T3',CASCADE=>TRUE,NO_INVALIDATE=>FALSE)
    We now have a simple table with a primary key index, with collected statistics.

    Next, we will execute two SQL statements without a 10046 trace enabled, just to avoid some of the confusing background SQL statements needed during the later parse, and we will set the fetch array size to 1000 to minimize the number of round trips between the server and client:
    SELECT /*+ INDEX(T3) */
      *
    FROM
      T3
    WHERE
      C1<=200;
     
    SELECT
      SYSDATE
    FROM
      DUAL;
     
    SET ARRAYSIZE 1000
    After flushing the buffer cache, we will again execute the two SQL statements above with an enabled 10046 trace:
    ALTER SYSTEM FLUSH BUFFER_CACHE;
    ALTER SYSTEM FLUSH BUFFER_CACHE;
      
    ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
    ALTER SESSION SET TRACEFILE_IDENTIFIER = '10046TESTING';
     
    SELECT /*+ INDEX(T3) */
      *
    FROM
      T3
    WHERE
      C1<=200;
     
    SELECT
      SYSDATE
    FROM
      DUAL;
     
    ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
    The raw 10046 trace file, just for the SQL statement of interest:
    =====================
    PARSING IN CURSOR #371254768 len=53 dep=0 uid=62 oct=3 lid=62 tim=184435767875 hv=1334288504 ad='7ffb8c1be40' sqlid='a75xc757sg83s'
    SELECT /*+ INDEX(T3) */
      *
    FROM
      T3
    WHERE
      C1<=200
    END OF STMT
    PARSE #371254768:c=0,e=699,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=216260220,tim=184435767874                                  <--- hard parse
    EXEC #371254768:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=216260220,tim=184435767947
    WAIT #371254768: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=184435767976
    WAIT #371254768: nam='db file scattered read' ela= 320 file#=4 block#=4145624 blocks=8 obj#=73036 tim=184435768358          <--- 8 for index
    WAIT #371254768: nam='db file scattered read' ela= 276 file#=4 block#=4145616 blocks=8 obj#=73035 tim=184435768704          <--- 8 for table
    FETCH #371254768:c=0,e=764,p=16,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=216260220,tim=184435768757
    WAIT #371254768: nam='SQL*Net message from client' ela= 110 driver id=1413697536 #bytes=1 p3=0 obj#=73035 tim=184435768890
    WAIT #371254768: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=73035 tim=184435768916
    WAIT #371254768: nam='db file scattered read' ela= 283 file#=4 block#=4145632 blocks=8 obj#=73035 tim=184435769273          <--- 8 for table
    FETCH #371254768:c=0,e=443,p=8,cr=10,cu=0,mis=0,r=199,dep=0,og=1,plh=216260220,tim=184435769349
    STAT #371254768 id=1 cnt=200 pid=0 pos=1 obj=73035 op='TABLE ACCESS BY INDEX ROWID T3 (cr=12 pr=24 pw=0 time=762 us cost=10 size=60800 card=200)'
    STAT #371254768 id=2 cnt=200 pid=1 pos=1 obj=73036 op='INDEX RANGE SCAN SYS_C008672 (cr=2 pr=8 pw=0 time=1012 us cost=1 size=0 card=200)'
     
    *** 2012-01-25 09:17:32.639
    WAIT #371254768: nam='SQL*Net message from client' ela= 1142603 driver id=1413697536 #bytes=1 p3=0 obj#=73035 tim=184436912005
    CLOSE #371254768:c=0,e=19,dep=0,type=0,tim=184436912120
    =====================
    Sending through TKPROF:
    tkprof or1122d_ora_11380_10046TESTING.trc or1122d_ora_11380_10046TESTING.txt
    A portion of the TKPROF output:
    ********************************************************************************
    SELECT /*+ INDEX(T3) */
      *
    FROM
      T3
    WHERE
      C1<=200
     
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute      2      0.00       0.00          0          0          0           0
    Fetch        2      0.00       0.00         24         12          0         200
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        5      0.00       0.00         24         12          0         200
     
    Misses in library cache during parse: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 62  
    Number of plan statistics captured: 1
     
    Rows (1st) Rows (avg) Rows (max)  Row Source Operation
    ---------- ---------- ----------  ---------------------------------------------------
           200        200        200  TABLE ACCESS BY INDEX ROWID T3 (cr=12 pr=24 pw=0 time=762 us cost=10 size=60800 card=200)
           200        200        200   INDEX RANGE SCAN SYS_C008672 (cr=2 pr=8 pw=0 time=1012 us cost=1 size=0 card=200)(object id 73036)
     
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                       3        0.00          0.00
      SQL*Net message from client                     3        1.14          1.14
      db file scattered read                          3        0.00          0.00
    ********************************************************************************
    Charles Hooper
  • 14. Re: Tkprof output question
    905989 Newbie
    Currently Being Moderated
    Hi Nikolay,

    You had
    ALTER SESSION SET STATISTICS_LEVEL = ALL;
    I believe STATISTICS_LEVEL = ALL will slow down the whole process as there is a bug in 11g and the timing will be three to four times slower?

    thanks
1 2 Previous Next

Legend

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