1 2 Previous Next 24 Replies Latest reply: Jan 30, 2012 8:19 AM by 905989 RSS

    Tkprof output question

    905989
      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
          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
            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
              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
                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
                  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
                    "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
                      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
                        Hi,

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

                        Regards
                        • 9. Re: Tkprof output question
                          Charles Hooper
                          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
                            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
                              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
                                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
                                  Charles Hooper
                                  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
                                    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