This discussion is archived
1 2 Previous Next 24 Replies Latest reply: Jan 30, 2012 6:19 AM by 905989 Go to original post RSS
  • 15. Re: Tkprof output question
    905989 Newbie
    Currently Being Moderated
    Thanks Charles I will try your example.

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


    >
    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
    you have a better chance if figuring that out from raw (non-tkprofed) trace files. Beware of rounding errors which often account for inconsistencies in response time calculations!

    If you need help understanding raw trace files, please refer to the a great book by Milsap and Holt, "Optimizing Oracle Performance".

    Best regards,
    Nikolay
  • 17. Re: Tkprof output question
    Mich Talebzadeh Explorer
    Currently Being Moderated
    Hi Charles:

    In your statement 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)
    
    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.
     .... For the first execution of the SQL statement, there were 11 physical block reads, 6 from the index and 5 from the table....
    Am I correct in that it refers to 11 physical I/O (PIO) and 6 PIO as opposed to 11 blocks or 6 blocks read? The units is always PIO which could be multi-block read as well as single-block read.

    However, the figures in TKPROF report under disk and query are always in block size.

    Cheers,

    Mich

    Edited by: Mich Talebzadeh on 25-Jan-2012 08:22
  • 18. Re: Tkprof output question
    CharlesHooper Expert
    Currently Being Moderated
    Mich Talebzadeh wrote:
    Hi Charles:

    In your statement 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)
    
    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.
    .... For the first execution of the SQL statement, there were 11 physical block reads, 6 from the index and 5 from the table....
    Am I correct in that it refers to 11 physical I/O (PIO) and 6 PIO as opposed to 11 blocks or 6 blocks read? The units is always PIO which could be multi-block read as well as single-block read.

    However, the figures in TKPROF report under disk and query are always in block size.

    Cheers,

    Mich
    Mich,

    The number of "db file sequential read" and the number of "db file scattered read" waits would tell you the number of physical I/Os performed. The statistics in the WAIT and STAT lines in the trace file are in terms of blocks, as of the release of Oracle Database 10.1 the word "blocks" actually appears on the WAIT lines, prior to 10.1 the phrase p2 would appear.

    Let's take a look just at the WAIT for the blocks and STAT entries from the section of the raw 10046 trace file that I posted:
    WAIT #371254768: nam='db file scattered read' ela= 320 file#=4 block#=4145624 blocks=8 obj#=73036 tim=184435768358
    WAIT #371254768: nam='db file scattered read' ela= 276 file#=4 block#=4145616 blocks=8 obj#=73035 tim=184435768704
    WAIT #371254768: nam='db file scattered read' ela= 283 file#=4 block#=4145632 blocks=8 obj#=73035 tim=184435769273
    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)'
    The above shows that there were 3 physical reads, but 24 blocks were read in those physical reads. The STAT lines show only the number of blocks - 12 consistent read blocks in total, and 24 physical blocks read from disk. The STAT lines do not tell how many physical reads.

    You can compare the above directly with the TKPROF output:
    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  ----------  ------------
      db file scattered read                          3        0.00          0.00
    I might not have understood your question.

    Charles Hooper
  • 19. Re: Tkprof output question
    Mich Talebzadeh Explorer
    Currently Being Moderated
    Hi Charles

    I ran your t3 table.

    First output from the raw trace file
    cat mydb_ora_21820_10046TESTING.trc|grep blocks
    WAIT #2: nam='db file scattered read' ela= 362 file#=8 block#=3099824 blocks=8 obj#=83120 tim=1327527546312091
    WAIT #2: nam='db file scattered read' ela= 324 file#=8 block#=3099816 blocks=8 obj#=83119 tim=1327527546312615
    WAIT #2: nam='db file scattered read' ela= 309 file#=8 block#=3099832 blocks=8 obj#=83119 tim=1327527546321980
    So we are talking three waits (three physical I/O PIO) with scattered reads and 24 physical block reads in total?

    Then I have the output from tkprof as follows:
    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       15      0.00       0.00         24         37          0         200
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total       18      0.00       0.00         24         37          0         200
    
    Misses in library cache during parse: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 97
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
        200  TABLE ACCESS BY INDEX ROWID T3 (cr=37 pr=24 pw=0 time=995 us cost=10 size=60800 card=200)
        200   INDEX RANGE SCAN SYS_C0016415 (cr=15 pr=8 pw=0 time=597 us cost=1 size=0 card=200)(object id 83120)
    
    
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                      16        0.00          0.00
      SQL*Net message from client                    16        0.00          0.02
      Disk file operations I/O                        1        0.00          0.00
      db file scattered read                          3        0.00          0.00
    ********************************************************************************
    So from the stat line we have pr=24 (8 from index + 16 from table). These are blocks

    Now looking at disk/query/current columns these are all blocks. That query 37 blocks include 24 physical read blocks

    So my understanding is that all the waits each one correpond to one physical I/O. They may be single or multi-block reads. So essentially all the outputs from trace is in blocks (physical or logical reads). The PIO correspond to type of wait (db sequential, db scattered etc).

    I think it makes more sense now.

    Cheers,

    Mich

    Edited by: Mich Talebzadeh on 25-Jan-2012 13:42
  • 20. Re: Tkprof output question
    905989 Newbie
    Currently Being Moderated
    Hi,

    Many thaanks for your help. I have learned fair bit.
    The following is the report from tkprof run as suggested by Charles.
    I need few clarifications and appreciate feedback.
    My questions are highlighted as below
    ****
    ==> Question
    ****
    SQL ID: 78kxqdhk1ubvq
    Plan Hash: 3995659421
    SELECT *
    FROM
     T WHERE OBJECT_ID = :B1
    
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          1         63          0           0
    Execute  72184      0.88       1.03          4         54          0           0
    Fetch    72184      1.46       9.87      81365     368659          0       71727
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total   144369      2.36      10.92      81370     368776          0       71727
    
    Misses in library cache during parse: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 96     (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)
    
    
    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.63
      db file scattered read                      14590        0.02          4.61
    ********************************************************************************
    
    ****
    ==>    These are stats for the loop that results in 71727 rows read into buffe?
    SELECT *
    FROM
     T WHERE OBJECT_ID = :B1
    ****
    
    DECLARE
            type array is table of t%ROWTYPE index by binary_integer;
            l_data array;
            l_rec t%rowtype;
    BEGIN
            SELECT
                    a.*
                    ,RPAD('*',4000,'*') AS PADDING1
                    ,RPAD('*',4000,'*') AS PADDING2
            BULK COLLECT INTO
            l_data
            FROM ALL_OBJECTS a;
            DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true );
            FOR rs IN 1 .. l_data.count
            LOOP
                    BEGIN
                            SELECT * INTO l_rec FROM t WHERE object_id = l_data(rs).object_id;
                    EXCEPTION
                      WHEN NO_DATA_FOUND THEN NULL;
                    END;
            END LOOP;
    END;
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        0      0.00       0.00          0          0          0           0
    Execute      1      9.88      11.58        322      48685          0           1
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        1      9.88      11.58        322      48685          0           1
    
    Misses in library cache during parse: 0
    Misses in library cache during execute: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 96
    
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                       1        0.00          0.00
      SQL*Net message from client                     1        0.00          0.00
    ********************************************************************************
    
    ****
    ==> This is what the client sent for the whole of PL/SQL block. It shows  one execution of PL/SQL block and the summary of CPU and elapsed time with 322 physiical block reads.
    ****
    SQL ID: 9babjv8yq8ru3
    Plan Hash: 0
    BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
    
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute      1      0.00       0.00          0          0          0           1
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        2      0.00       0.00          0          0          0           1
    
    Misses in library cache during parse: 0
    Optimizer mode: ALL_ROWS
    Parsing user id: 96
    
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                       1        0.00          0.00
      SQL*Net message from client                     1        0.00          0.00
    
    ****
    ==> This one I can ignore
    ****
    
    ********************************************************************************
    
    OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute      2      9.88      11.58        322      48685          0           2
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        3      9.88      11.58        322      48685          0           2
    
    Misses in library cache during parse: 0
    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.00          0.00
      log file sync                                   1        0.00          0.00
    
    
    OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse       12      0.00       0.01          1         63          0           0
    Execute  72218      0.89       1.04          4         55          2           1
    Fetch    72231      1.46       9.87      81370     368776          0       71773
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total   144461      2.36      10.93      81375     368894          2       71774
    
    Misses in library cache during parse: 11
    Misses in library cache during execute: 10
    
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      db file sequential read                     12469        0.00          2.63
      Disk file operations I/O                        3        0.00          0.00
      db file scattered read                      14590        0.02          4.61
    
    72186  user  SQL statements in session.
       34  internal SQL statements in session.
    72220  SQL statements in session.
    ********************************************************************************
    Trace file: test.trc
    Trace file compatibility: 11.1.0.7
    Sort options: default
    
           1  session in tracefile.
       72186  user  SQL statements in trace file.
          34  internal SQL statements in trace file.
       72220  SQL statements in trace file.
          14  unique SQL statements in trace file.
      532743  lines in trace file.
          17  elapsed seconds in trace file.
    
    ****
    ==> Are the overall totals the statistics that needs to be quoted. Non-recursive is the SQL that client sent and recursive is the SQL executed from the SQL client sent
        The total CPU for the whole query is it 9.88+2.36 seconds and total wait time is 11.58+10.93?
    ****
    Thanks again
  • 21. Re: Tkprof output question
    CharlesHooper Expert
    Currently Being Moderated
    902986 wrote:
    Hi,

    Many thaanks for your help. I have learned fair bit.
    The following is the report from tkprof run as suggested by Charles.
    I need few clarifications and appreciate feedback.
    My questions are highlighted as below
    ****
    ==> Question
    ****
    I tried to set up a script that duplicates your test case. 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 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:
    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;
    When you execute the above script, near the start of the trace file you should find something similar to this:
    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 valiue.

    Near the end of the trace file you should find something similar to this:
    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.

    (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. This is the summary from TKPROF for my test run:
    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.
    The above output is a bit misleading. If we switch back to the raw 10046 file, we might find something like this very close to the end of the trace file:
    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 and 9.631079 seconds of elapsed time, yet that is not in agreement with the above TKPROF output. Let's scan up through the 10046 trace file to find the PARSE line for 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
    Using thr tim= values for the EXEC and PARSE calls: (2302533148184 - 2302523516952) / 1000000 = 9.631232 seconds elapsed between the calls, so it actually required 9.6 seconds to execute the non-recursive SQL statement. You can read about some of the limitations of TKPROF involving recursive SQL statements in the book "Optimizing Oracle Performance":
    http://books.google.com/books?id=mvJW6t7mYU0C&pg=PT17
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          1         63          0           0
    Execute  72184      0.88       1.03          4         54          0           0
    Fetch    72184      1.46       9.87      81365     368659          0       71727
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total   144369      2.36      10.92      81370     368776          0       71727
    
    Misses in library cache during parse: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 96     (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)
    
    
    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.63
    db file scattered read                      14590        0.02          4.61
    ********************************************************************************
    ==> These are stats for the loop that results in 71727 rows read into buffe?
    Not "read into the buffer". It is more accurate to state: 71727 rows are returned in 72184 executions of the SQL statement.
     
    DECLARE
    type array is table of t%ROWTYPE index by binary_integer;
    l_data array;
    l_rec t%rowtype;
    BEGIN
    SELECT
    a.*
    ,RPAD('*',4000,'*') AS PADDING1
    ,RPAD('*',4000,'*') AS PADDING2
    BULK COLLECT INTO
    l_data
    FROM ALL_OBJECTS a;
    DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true );
    FOR rs IN 1 .. l_data.count
    LOOP
    BEGIN
    SELECT * INTO l_rec FROM t WHERE object_id = l_data(rs).object_id;
    EXCEPTION
    WHEN NO_DATA_FOUND THEN NULL;
    END;
    END LOOP;
    END;
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        0      0.00       0.00          0          0          0           0
    Execute      1      9.88      11.58        322      48685          0           1
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        1      9.88      11.58        322      48685          0           1
    
    Misses in library cache during parse: 0
    Misses in library cache during execute: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 96
    
    Elapsed times include waiting on following events:
    Event waited on                             Times   Max. Wait  Total Waited
    ----------------------------------------   Waited  ----------  ------------
    SQL*Net message to client                       1        0.00          0.00
    SQL*Net message from client                     1        0.00          0.00
    ********************************************************************************
    ==> This is what the client sent for the whole of PL/SQL block. It shows one execution of PL/SQL block and the summary of CPU and elapsed time with 322 physiical block reads.
    As I demonstrated above, the statistics output by TKPROF can be misleading. Take a look in your raw 10046 trace file, and locate the EXEC line for the above PL/SQL block. My trace file showed p=3231,cr=267427: that is 3,231 blocks read from disk with 267,427 consistent gets for the non-recursive SQL.
    ==> Are the overall totals the statistics that needs to be quoted. Non-recursive is the SQL that client sent and recursive is the SQL executed from the SQL client sent
    The total CPU for the whole query is it 9.88+2.36 seconds and total wait time is 11.58+10.93?

    Thanks again
    I think that what you wrote above is the intention of the TKPROF output, but it might not work out exactly that way. Keep in mind that the execution time of the non-recursive SQL includes the execution time of the recursive SQL, even though TKPROF might not show that relationship.

    Charles Hooper
  • 22. Re: Tkprof output question
    905989 Newbie
    Currently Being Moderated
    Hi Charles.

    This is excellent and thanks for your time.
    I just followed your example for table T4. Trace file was created and I just ran
    Tkprof <raw_trace> tkproft.txt sys=no
    I agree with you that it is best to look at the trace file and work out the ambiguity from the trace file rather than tkprof report. The only difference is that in my all_objects I have 72227 rows slightly more than yours.

    Can you please check if you see this
    SELECT *
    FROM
     T4 WHERE OBJECT_ID = :B1
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute  72227      0.95       1.02          0          0          0           0
    Fetch    72227      1.22       1.23       1232     216839          0       72226
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total   144455      2.17       2.26       1232     216839          0       72226
    And for all recursive I get:
    OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse       17      0.10       0.10          0          0          0           0
    Execute  72345      0.96       1.03         16        376          0           0
    Fetch    72362      7.67       8.03       3091     264121          0      144578
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total   144724      8.74       9.17       3107     264497          0      144578
    This is different from yours. Note the rows. It is possible that your output is not showing the matrices for BULK COLLECT?

    Thanks
  • 23. Re: Tkprof output question
    CharlesHooper Expert
    Currently Being Moderated
    902986 wrote:
    Hi Charles.

    This is excellent and thanks for your time.
    I just followed your example for table T4. Trace file was created and I just ran
    Tkprof <raw_trace> tkproft.txt sys=no
    I agree with you that it is best to look at the trace file and work out the ambiguity from the trace file rather than tkprof report. The only difference is that in my all_objects I have 72227 rows slightly more than yours.

    Can you please check if you see this
    SELECT *
    FROM
    T4 WHERE OBJECT_ID = :B1
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute  72227      0.95       1.02          0          0          0           0
    Fetch    72227      1.22       1.23       1232     216839          0       72226
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total   144455      2.17       2.26       1232     216839          0       72226
    And for all recursive I get:
    OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse       17      0.10       0.10          0          0          0           0
    Execute  72345      0.96       1.03         16        376          0           0
    Fetch    72362      7.67       8.03       3091     264121          0      144578
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total   144724      8.74       9.17       3107     264497          0      144578
    This is different from yours. Note the rows. It is possible that your output is not showing the matrices for BULK COLLECT?

    Thanks
    I put together a blog article that attempts to explain what happened in my results. See the following blog article (the above test case starts roughly 1/3 the way down the page):
    http://hoopercharles.wordpress.com/2012/01/30/parent-child-relationships-and-the-questions-left-unanswered-by-tkprof-re-learning-something-old/

    In short, what is happening is that the 11.2.0.1 TKPROF is losing some of the statistics. Specifically, it is only accounting for the disk (physical block read) and query (consistent gets) statistics from the recursive SQL statement that was found in the trace file (SELECT * FROM T4 WHERE OBJECT_ID = :B1) and it loses the statistics from the other cursors. In my test case, there were a total of 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 found in the trace file. TKPROF lost track of 1,991 blocks that were read from disk, 49,108 consistent gets, and at least 2.18 seconds of elapsed time.

    The end result is that you cannot simply add the statistics found in the non-recursive and recursive sections of the TKPROF output and expect to determine the statistic totals found in the trace file.

    Charles Hooper
    http://hoopercharles.wordpress.com/
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 24. Re: Tkprof output question
    905989 Newbie
    Currently Being Moderated
    Many thanks Sir for detailed explanation and follow up
1 2 Previous Next

Legend

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