Parent-Child Relationships and the Questions Left Unanswered by TKPROF, Re-Learning Something Old

January 30, 2012

As we have seen in the past, TKPROF output sometimes lies, and in a recent OTN thread I was reminded of another case or two where TKPROF output may be misleading.  In the OTN thread, the original poster (OP) started the thread by asking a simple question about an execution plan that appeared in a TKPROF output.  Below is an execution plan that is similar to the one posted by the OP:

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  TABLE ACCESS BY INDEX ROWID T4 (cr=3 pr=16 pw=0 time=1274 us cost=2 size=97 card=1)
         1          1          1   INDEX RANGE SCAN IND_T4_OBJECT_ID (cr=2 pr=8 pw=0 time=620 us cost=1 size=0 card=1)(object id 102460) 

For the above execution plan, the trace file was created on Oracle Database 11.2.0.2 and processed with a 11.2.0.1 client with the patch that fixes the ODBC problem.  The original poster (OP) in the OTN thread posed a question about the cr= (consistent gets blocks) and pr= (physical read blocks) statistics.  In the above, the INDEX RANGE SCAN operation shows cr=2 pr=8, and the TABLE ACCESS BY INDEX ROWID operation shows cr=3 pr=16.  The OP questioned whether the TABLE ACCESS BY INDEX ROWID operation statistics included the INDEX RANGE SCAN operation statistics for a total of 3 consistent gets and 16 physical blocks read from disk, or if the TABLE ACCESS BY INDEX ROWID operation statistics are in addition to the INDEX RANGE SCAN operation statistics for a total of 5 consistent gets and 24 physical blocks read from disk.  As sometimes happens with Internet forums, people responding to questions sometimes provide conflicting answers; in this case, at least one person stated that each interpretation is correct.

The OP’s actual Row Source Operation execution plan showed the following:

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 an attempt to provide the OP with answers to all of his unanswered questions to that point in the thread, I provided the following response:

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.

OK, so if you believe the above quote, the child statistics are rolled into the parent’s statistics, the EXPLAIN option of TKPROF may write incorrect execution plans to the output file especially when bind variables are used, and the original trace file included SQL statements marked with dep=0 or dep=1.  In the thread there was disagreement on the first point, so let’s throw together a very short test case to determine if that point is correct.

First, we will create a simple table with a primary key index, insert  200 rows into the table, and collect statistics on that table:

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) 

Next, I want to make certain that the two SQL statements that will be used in the test script will already exist in the library cache (so that we can test whether or not enabling a 10046 trace will cause a hard parse when the SQL statements are re-executed).  I also will set the fetch array size to 1000 to minimize the number of round trips between the server and client (the default fetch array size is 15 for SQL*Plus, and that value would make the generated trace file a bit more difficult to read due to the extra FETCH and SQL*Net wait events).  The second SQL statement, intended to make certain that the STAT lines for the first SQL statement will be written to the 10046 trace file, is only necessary prior to Oracle Database 11.1.0.6:

SELECT /*+ INDEX(T3) */
  *
FROM
  T3
WHERE
  C1<=200;

SELECT
  SYSDATE
FROM
  DUAL;

SET ARRAYSIZE 1000

Now for the final section of the test case script: flush the buffer cache, enable a 10046 trace, and execute the two SQL statements:

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';  

Let’s start by taking a look at the raw 10046 trace file, slightly marked up:

=====================
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
===================== 

The above shows a hard parse, 8 blocks read by multi-block read for the index, and 16 blocks read by multi-block read for the table.  If we process the trace file with TKPROF, a portion of the TKPROF output should look like this:

********************************************************************************
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
******************************************************************************** 

By examining the raw trace file, we are able to confirm that the pr=24 statistic in the first row of the Row Source Execution plan includes the 16 blocks for the table and the 8 blocks from the index, as identified in the raw 10046 trace file.

—

The OP later asked a handful of questions, including whether or not he should add the statistics found in the OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS section of the TKPROF output to the statistics found in the OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS section.  My first thought was to modify my original test case script shown above like this, so that there is a logging trigger on the T3 table that records changes made to the T3 table in the T4 table:

DROP TABLE T3 PURGE;
DROP TABLE T4 PURGE;

CREATE TABLE T3 (
  C1 NUMBER,
  C2 VARCHAR2(300),
  PRIMARY KEY(C1));

CREATE TABLE T4(
  NEW_C1 NUMBER,
  OLD_C2 VARCHAR2(300),
  NEW_C2 VARCHAR2(300),
  LOG_MODIFIED_USER_ID VARCHAR2(30) DEFAULT USER,
  LOG_MODIFIED_DATE DATE DEFAULT SYSDATE,
  LOG_TRANSACTION_TYPE VARCHAR2(1))
  PCTFREE 0
  PCTUSED 99;

CREATE OR REPLACE TRIGGER HPM_T3 AFTER
INSERT OR DELETE OR UPDATE OF C1, C2 ON T3
REFERENCING OLD AS OLDDATA NEW AS NEWDATA FOR EACH ROW
BEGIN
  IF UPDATING THEN
    IF (NVL(:OLDDATA.C1,0.0000019) <> NVL(:NEWDATA.C1,0.0000019)) OR (NVL(:OLDDATA.C2,'3!3D$FF') <> NVL(:NEWDATA.C2,'3!3D$FF'))  THEN
     INSERT INTO T4 (
      NEW_C1,
      OLD_C2,
      NEW_C2,
      LOG_TRANSACTION_TYPE)
     VALUES (
      :NEWDATA.C1,
      :OLDDATA.C2,
      :NEWDATA.C2,
      'U');
    END IF;
  END IF;

  IF DELETING THEN
    INSERT INTO T4 (
      NEW_C1,
      OLD_C2,
      LOG_TRANSACTION_TYPE)
    VALUES (
      :OLDDATA.C1,
      :OLDDATA.C2,
      'D');
  END IF;

  IF INSERTING THEN
    INSERT INTO T4 (
      NEW_C1,
      NEW_C2,
      LOG_TRANSACTION_TYPE)
    VALUES (
      :NEWDATA.C1,
      :NEWDATA.C2,
      'I');
  END IF;
END;
/

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)

SELECT /*+ INDEX(T3) */
  *
FROM
  T3
WHERE
  C1<=200;

SELECT
  SYSDATE
FROM
  DUAL;

SET ARRAYSIZE 1000 

Then I would add a new section to the second half of the original test script to update 50 rows of table T3:

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 = '10046TESTING2';

SELECT /*+ INDEX(T3) */
  *
FROM
  T3
WHERE
  C1<=200;

SELECT
  SYSDATE
FROM
  DUAL;

ALTER SESSION SET TRACEFILE_IDENTIFIER = '10046TESTING3';

UPDATE
  T3
SET
  C1=C1+1000,
  C2='UPDATED BY 1000'
WHERE
  C1<=50;

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF'; 

–

I decided to abandon that approach, and instead try to reproduce the test script that the OP was attempting to use.  My best guess is that the OP’s test script looks similar to the following:

CREATE TABLE T4 AS
SELECT
  *
FROM
  ALL_OBJECTS;

ALTER TABLE T4 ADD (
  PADDING1 VARCHAR2(4000),
  PADDING2 VARCHAR2(4000));

CREATE INDEX IND_T4_OBJECT_ID ON T4(OBJECT_ID);

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T4',CASCADE=>TRUE,NO_INVALIDATE=>FALSE)

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

ALTER SESSION SET TRACEFILE_IDENTIFIER = '10046_FIND_ME';
EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true );

DECLARE
        type array is table of t4%ROWTYPE index by binary_integer;
        l_data array;
        l_rec t4%rowtype;
BEGIN
        SELECT
                a.*
                ,RPAD('*',4000,'*') AS PADDING1
                ,RPAD('*',4000,'*') AS PADDING2
        BULK COLLECT INTO
        l_data
        FROM ALL_OBJECTS a;

        FOR rs IN 1 .. l_data.count
        LOOP
                BEGIN
                        SELECT * INTO l_rec FROM t4 WHERE object_id = l_data(rs).object_id;
                EXCEPTION
                  WHEN NO_DATA_FOUND THEN NULL;
                END;
        END LOOP;
END;
/

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE; 

In the script I set the NO_INVALIDATE parameter of the DBMS_STATS.GATHER_TABLE_STATS procedure to FALSE so that the session cursor cache would be flushed of all references to the T4 table, which then leads to the SQL statements appearing in the trace file on repeated executions if you need to execute the script a couple of times from that line of the test script to the end.  I also moved the DBMS_MONITOR.SESSION_TRACE_ENABLE call outside of the anonymous PL/SQL block so that PL/SQL block would be included in the trace file.

After executing the test script, I found the following lines near the start of the generated 10046 trace file:

PARSING IN CURSOR #481810328 len=63 dep=0 uid=64 oct=47 lid=64 tim=2302523409025 hv=2690357649 ad='3edbc1610' sqlid='dsvxr0ah5r6cj'
BEGIN DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true ); END;
END OF STMT 

In the above, note the tim=2302523409025 value.  Near the end of the 10046 trace file I found the following lines:

PARSING IN CURSOR #481810424 len=48 dep=0 uid=64 oct=47 lid=64 tim=2302533226450 hv=3127860446 ad='3eb311428' sqlid='80u1a4kx6yr6y'
BEGIN DBMS_MONITOR.SESSION_TRACE_DISABLE; END;
END OF STMT

In the above, note the tim=2302533226450 value.

We are able to determine the elapsed time between these two calls with simple mathematics: (2302533226450 – 2302523409025) / 1000000 = 9.817425 seconds elapsed time in the trace file between the start of the 10046 trace and the call to end the 10046 trace.

Now, let’s see if we are able to find another case where TKPROF lies.  We are able to find a hint of the problems in the book “Optimizing Oracle Performance” (see page xv and page 90).  Here is the TKPROF summary for my execution of the test script (generated with this command: tkprof or1122p_ora_19180_10046_FIND_ME.trc or1122p_ora_19180_10046_FIND_ME.txt):

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      3      5.36       5.34          0          0          0           3
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      5.36       5.35          0          0          0           3

Misses in library cache during parse: 2
Misses in library cache during execute: 1

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2        0.10          0.10

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute  72720      0.99       1.08          0          0          0           0
Fetch    72720      1.01       1.02       1240     218319          0       72719
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   145441      2.01       2.10       1240     218319          0       72719

Misses in library cache during parse: 1

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                      1047        0.00          0.25
  db file scattered read                        182        0.00          0.10
  asynch descriptor resize                      291        0.00          0.00

    4  user  SQL statements in session.
    0  internal SQL statements in session.
    4  SQL statements in session.
********************************************************************************
Trace file: or1122p_ora_19180_10046_FIND_ME.trc
Trace file compatibility: 11.1.0.7
Sort options: default

       1  session in tracefile.
       4  user  SQL statements in trace file.
       0  internal SQL statements in trace file.
       4  SQL statements in trace file.
       4  unique SQL statements in trace file.
  220086  lines in trace file.
       9  elapsed seconds in trace file. 

Does the above output indicate that my anonymous PL/SQL block completed in 5.35 seconds, and that the recursive call accounted for 2.1 seconds of that time?  Or, should we add the non-recursive and recursive elapsed times together to determine the total time?  Should we add the total blocks read from disk displayed in the non-recursive portion (0) to the total blocks read from disk displayed in the recursive portion (1240) to determine the total number of blocks read from disk during the execution?  The above statistics indicate that there were 1047 waits for the db file sequential read wait event and 182 waits for the db file scattered read wait event in the OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS section of the TKPROF output.  We know that each db file sequential read wait event represents reading one block from disk, and that each db file scattered read wait event represents reading at least 2 blocks from disk.  Let’s try some simple mathematics: 1047 + (2 * 182) = 1411 – the wait event statistics for the OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS section of the TKPROF output indicate that at least 1,411 blocks should have been read from disk, while the TKPROF output only shows 1,240 blocks.  Is TKPROF lying?

Let’s take another look at the raw 10046 trace file.  Very close to the end of the trace file I found the following line:

EXEC #481810328:c=9266459,e=9631079,p=3231,cr=267427,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=2302533148184 

The above indicates that cursor number 481810328 consumed 9.266459 seconds of CPU time, 9.631079 seconds of elapsed time, read 3,231 blocks from disk, and performed 267,427 consistent gets when that cursor was executed – yet that is not in agreement with the above TKPROF output (the numbers are greater than even the non-recursive plus recursive statistics would suggest).  If we search upward in the trace file, we are able to find the code that is associated with cursor number 481810328:

PARSING IN CURSOR #481810328 len=610 dep=0 uid=64 oct=47 lid=64 tim=2302523516952 hv=468044383 ad='3edbc2e48' sqlid='8zytk5ndybkkz'
DECLARE
        type array is table of t4%ROWTYPE index by binary_integer;
        l_data array;
        l_rec t4%rowtype;
BEGIN
        SELECT
                a.*
                ,RPAD('*',4000,'*') AS PADDING1
                ,RPAD('*',4000,'*') AS PADDING2
        BULK COLLECT INTO
        l_data
        FROM ALL_OBJECTS a;
        FOR rs IN 1 .. l_data.count
        LOOP
                BEGIN
                        SELECT * INTO l_rec FROM t4 WHERE object_id = l_data(rs).object_id;
                EXCEPTION
                  WHEN NO_DATA_FOUND THEN NULL;
                END;
        END LOOP;
END;
END OF STMT 

That is our anonymous PL/SQL block, which would fall into the non-recursive totals that shows a total of 5.36 seconds of CPU time, 5.35 seconds of elapsed time, 0 blocks read from disk, and 0 consistent gets.

So, did TKPROF answer more questions than it generated?

I was curious, so I processed the trace file using my Hyper-Extended Oracle Performance Monitor program (AKA: Toy Project for Performance Monitoring).  This is the what was written to one of the output files:

Total for Trace File:
|PARSEs       3|CPU S    0.000000|CLOCK S    0.006473|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      3|
|EXECs    72723|CPU S   10.264864|CLOCK S   10.715043|ROWs        3|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs   72720|CPU S    1.014008|CLOCK S    1.021754|ROWs    72719|PHY RD BLKs      1240|CON RD BLKs (Mem)    218319|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|

Wait Event Summary:
SQL*Net message to client           0.000010  On Client/Network   Min Wait:     0.000003  Avg Wait:     0.000005  Max Wait:     0.000007  Waits:      2
SQL*Net message from client         0.107469  On Client/Network   Min Wait:     0.006123  Avg Wait:     0.053735  Max Wait:     0.101346  Waits:      2
db file sequential read             0.254673  On DB Server        Min Wait:     0.000023  Avg Wait:     0.000243  Max Wait:     0.001280  Waits:   1047
db file scattered read              0.100087  On DB Server        Min Wait:     0.000088  Avg Wait:     0.000550  Max Wait:     0.004496  Waits:    182
asynch descriptor resize            0.000359  On DB Server        Min Wait:     0.000000  Avg Wait:     0.000001  Max Wait:     0.000004  Waits:    291

Total for Similar SQL Statements in Each Group:
----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1 
First Reference: Cursor 621   Ver 1   Parse at 0.000000 SQL_ID='dsvxr0ah5r6cj'
|PARSEs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|EXECs        1|CPU S    0.000000|CLOCK S    0.000941|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 0.00%  CLOCK S 0.01%
  *    0.101349 seconds of time related to client/network events

----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1 
First Reference: Cursor 621   Ver 2   Parse at 0.107927 SQL_ID='8zytk5ndybkkz'
|PARSEs       1|CPU S    0.000000|CLOCK S    0.004720|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        1|CPU S    9.266459|CLOCK S    9.631079|ROWs        1|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 82.16%  CLOCK S 82.05%
  *    0.006130 seconds of time related to client/network events
|    ++++++++++++++++||    ++++++++++++++++|

----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1 
First Reference: Cursor 648   Ver 1   Parse at 2.291806 SQL_ID='5k52u3cqwkkmw'
|PARSEs       1|CPU S    0.000000|CLOCK S    0.000441|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs    72720|CPU S    0.998405|CLOCK S    1.081928|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs   72720|CPU S    1.014008|CLOCK S    1.021754|ROWs    72719|PHY RD BLKs      1240|CON RD BLKs (Mem)    218319|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 17.84%  CLOCK S 17.92%
  *    0.075437 seconds of time related data file I/O
|                ++++||                ++++|

----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1 
First Reference: Cursor 717   Ver 1   Parse at 9.817425 SQL_ID='80u1a4kx6yr6y'
|PARSEs       1|CPU S    0.000000|CLOCK S    0.001312|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        1|CPU S    0.000000|CLOCK S    0.001095|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 0.00%  CLOCK S 0.02%

End of Summary, Detail Follows
--------------------------------------------------------------------------------------------------
----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1
|PARSEs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|EXECs        1|CPU S    0.000000|CLOCK S    0.000941|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|

Statement Depth 0 (Application Code)
Cursor 621   Ver 1   Parse at 0.000000 SQL_ID='dsvxr0ah5r6cj'  Similar Cnt 1
|PARSEs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|EXECs        1|CPU S    0.000000|CLOCK S    0.000941|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 0.00%  CLOCK S 0.01%

BEGIN DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true ); END;
------------
----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.004720|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        1|CPU S    9.266459|CLOCK S    9.631079|ROWs        1|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|

Statement Depth 0 (Application Code)
Cursor 621   Ver 2   Parse at 0.107927 SQL_ID='8zytk5ndybkkz'  (TD Prev 0.107927)  Similar Cnt 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.004720|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        1|CPU S    9.266459|CLOCK S    9.631079|ROWs        1|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 82.16%  CLOCK S 82.05%
|    ++++++++++++++++||    ++++++++++++++++|
DECLARE
        type array is table of t4%ROWTYPE index by binary_integer;
        l_data array;
        l_rec t4%rowtype;
BEGIN
        SELECT
                a.*
                ,RPAD('*',4000,'*') AS PADDING1
                ,RPAD('*',4000,'*') AS PADDING2
        BULK COLLECT INTO
        l_data
        FROM ALL_OBJECTS a;
        FOR rs IN 1 .. l_data.count
        LOOP
                BEGIN
                        SELECT * INTO l_rec FROM t4 WHERE object_id = l_data(rs).object_id;
                EXCEPTION
                  WHEN NO_DATA_FOUND THEN NULL;
                END;
        END LOOP;
END;
------------
----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.000441|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs    72720|CPU S    0.998405|CLOCK S    1.081928|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs   72720|CPU S    1.014008|CLOCK S    1.021754|ROWs    72719|PHY RD BLKs      1240|CON RD BLKs (Mem)    218319|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|

Statement Depth 1 (Trigger Code)
Cursor 648   Ver 1   Parse at 2.291806 SQL_ID='5k52u3cqwkkmw'  (TD Prev 2.183879)  Similar Cnt 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.000441|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs    72720|CPU S    0.998405|CLOCK S    1.081928|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs   72720|CPU S    1.014008|CLOCK S    1.021754|ROWs    72719|PHY RD BLKs      1240|CON RD BLKs (Mem)    218319|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 17.84%  CLOCK S 17.92%
|                ++++||                ++++|
SELECT * FROM T4 WHERE OBJECT_ID = :B1

       (Rows 1)   TABLE ACCESS BY INDEX ROWID T4 (cr=3 pr=16 pw=0 time=1274 us cost=2 size=97 card=1)
       (Rows 1)    INDEX RANGE SCAN IND_T4_OBJECT_ID (cr=2 pr=8 pw=0 time=620 us cost=1 size=0 card=1)

------------
----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.001312|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        1|CPU S    0.000000|CLOCK S    0.001095|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|

Statement Depth 0 (Application Code)
Cursor 717   Ver 1   Parse at 9.817425 SQL_ID='80u1a4kx6yr6y'  (TD Prev 7.525619)  Similar Cnt 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.001312|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        1|CPU S    0.000000|CLOCK S    0.001095|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 0.00%  CLOCK S 0.02%

BEGIN DBMS_MONITOR.SESSION_TRACE_DISABLE; END;

So, what does the above indicate when compared with the TKPROF output?

Let’s look at the summary again from TKPROF:

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      3      5.36       5.34          0          0          0           3
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      5.36       5.35          0          0          0           3

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute  72720      0.99       1.08          0          0          0           0
Fetch    72720      1.01       1.02       1240     218319          0       72719
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   145441      2.01       2.10       1240     218319          0       72719 

And the summary from my program:

Total for Trace File:
|PARSEs       3|CPU S    0.000000|CLOCK S    0.006473|PHY RD BLKs         0|CON RD BLKs (Mem)         0|
|EXECs    72723|CPU S   10.264864|CLOCK S   10.715043|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|
|FETCHs   72720|CPU S    1.014008|CLOCK S    1.021754|PHY RD BLKs      1240|CON RD BLKs (Mem)    218319| 

My program double counted the CPU time and elapsed time (and ? … see below) from the recursive calls.  TKPROF only reported the consistent gets (218,319) and physical blocks read from disk (1,240) from the recursive FETCH lines in the trace file, but discarded those statistics from the non-recursive EXEC lines in the trace file.  That possibly explans why the number of db file single block read waits plus two times the number of db file scattered read waits exceeds the number reported in the disk column of the TKPROF output:

1047 + (2 * 182) = 1411 > 1200

The partially interesting item is that the db file scattered read waits, on average, read 12.00 blocks at a time, and the many of the db file scattered read waits are attributed to a mysterious cursor #482246872.  Another output of my program is an Excel spreadsheet that lists all wait events found in the trace file.  I added the following formula in cell F2 and copied that formula down to the last wait event line:

=IF(C2="db file sequential read",VALUE(MID(D2,FIND("blocks=",D2)+7,FIND(" ",D2,FIND("blocks",D2)+1) - (FIND("blocks=",D2)+7))),"")

I added the following formula in cell G2 and copied that formula down to the last wait event line:

=IF(C2="db file scattered read",VALUE(MID(D2,FIND("blocks=",D2)+7,FIND(" ",D2,FIND("blocks",D2)+1) - (FIND("blocks=",D2)+7))),"")

With those two formulas in place, I was able to determine the actual number of physical block reads, and whether or not the blocks were read one at a time, or more than one block at a time.  The resulting Excel spreadsheet looks like this:

…

…

 

So, the above screen captures show that there were 9.8159 seconds in the trace file between the first and last tim= values.  The last of the above screen captures shows there were in total 1,047 single block reads (db file sequential read waits) and 182 multi-block reads (db file scattered read waits), with a total of 2,184 blocks read by multi-block read for an average of 12 blocks per multi-block read.

Let’s take another look at the other output file from my program:

Total for Trace File:
|PARSEs       3|CPU S    0.000000|CLOCK S    0.006473|PHY RD BLKs         0|CON RD BLKs (Mem)         0|
|EXECs    72723|CPU S   10.264864|CLOCK S   10.715043|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|
|FETCHs   72720|CPU S    1.014008|CLOCK S    1.021754|PHY RD BLKs      1240|CON RD BLKs (Mem)    218319|  

Well, it seems that the recursive SQL has caused a bit of a problem for my program.  The 1,240 physical block reads found on the FETCHs line are actually included in the 3,231 (1,047 + 2,184) physical block reads found on the EXECs line.

—

As a final self-answering question, which is worse: that TKPROF reports only 1,240 physical block reads, or that my program double-counts these 1,240 physical block reads and suggest that there were 4,471 physical block reads?  Maybe we should just ignore the recursive SQL statistics by checking an option box in my program:

Total for Trace File:
|PARSEs       2|CPU S    0.000000|CLOCK S    0.006032|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      2|
|EXECs        3|CPU S    9.266459|CLOCK S    9.633115|ROWs        3|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0| 

That option in my program fixed the CPU seconds, elapsed time, total physical blocks read, and total consistent gets, but now the number of EXECs, FETCHs, and ROWs do not match what is found in the raw 10046 trace file.

As the above Excel output and my program’s fixed output demonstrates, sometimes there is no replacement for examining the raw 10046 trace files.