This discussion is archived
3 Replies Latest reply: Mar 16, 2010 12:34 AM by 649748 RSS

cpu in tkprof (or 10046 raw file)

649748 Newbie
Currently Being Moderated
We have cpu time in tkprof report file or 10046 raw file. My question is:

If the system is cpu bound so that the session traced has latency to get the cpu, will the cpu in tkprof include such latency?

e.g
a session is on cpu for 10 second, but to get that 10 second cpu, the total latency is about 10 second (let's not consider the wait event, such as IO, and I think there is no wait event about cpu: waiting for cpu), will the cpu time show in 10046 trace file or tkrpof be 20 seconds? I have no good environment to test.

To test it. we could use solaris and bind the session to one cpu, and then write a perl to loop forever, in this case, the oracle session will experience a long latency to get the cpu.

I think , for solaris, the cpu in 10046 might not include the latency as solaris has microstate accounting, so oracle might use it to get the cpu time accurately, but for other OS without microstate accounting, I am wondering whether the cpu time in 10046 raw trace file include latency or not.
  • 1. Re: cpu in tkprof (or 10046 raw file)
    Taral Journeyer
    Currently Being Moderated
    You can sample v$mystat and see CPU usage.
    CPU used when call started
    CPU used by this session
  • 2. Re: cpu in tkprof (or 10046 raw file)
    CharlesHooper Expert
    Currently Being Moderated
    My first thought is that the CPU time should not include the time spent waiting in the CPU run queue. This is partially based on Cary Millsap's "Optimizing Oracle Performance" book and his comment in this blog article:
    http://hoopercharles.wordpress.com/2010/02/05/faulty-quotes-6-cpu-utilization/

    I saw different results with Oracle 11.1.0.7 running on an under-powered Windows box before and after I added an artifical load to the box. The test case was built like this:
    CREATE TABLE T1 (
      C1 VARCHAR2(10),
      C2 VARCHAR2(100),
      PRIMARY KEY (C1));
    
    INSERT INTO T1 NOLOGGING
    SELECT
      'A'||TO_CHAR(ROWNUM,'0000000'),
      RPAD('A',100,'A')
    FROM
      DUAL
    CONNECT BY
      LEVEL<=200000;
    
    COMMIT;
    
    EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE)
    I used a utility that would allow me to simultaneously generate a 10046 trace at level 8, and a DBMS_XPLAN showing actuals without displaying the results to the screen (you could use SET AUTOTRACE TRACEONLY STATISTICS to disable query output to the screen in SQL*Plus). The query that I ran multiple times is this one:
    SELECT /*+ USE_NL(T11 T12 T13 T14 T15 T16 T17 T18) */
      T11.C1,
      T11.C2,
      T12.C1,
      T12.C2,
      T13.C1,
      T13.C2,
      T14.C1,
      T14.C2,
      T15.C1,
      T15.C2,
      T16.C1,
      T16.C2,
      T17.C1,
      T17.C2,
      T18.C1,
      T18.C2
    FROM
      T1 T11,
      T1 T12,
      T1 T13,
      T1 T14,
      T1 T15,
      T1 T16,
      T1 T17,
      T1 T18
    WHERE
      T11.C1=T12.C1
      AND T11.C1=T13.C1
      AND T11.C1=T14.C1
      AND T11.C1=T15.C1
      AND T11.C1=T16.C1
      AND T11.C1=T17.C1
      AND T11.C1=T18.C1
      AND T11.C1 BETWEEN 'A 0000000' AND 'A 0200000';
    I executed the above query multiple times until no physical reads were observed.

    With no other load, the DBMS_XPLAN output:
    SQL_ID  9tnwsdrsbundx, child number 1
    -------------------------------------
    SELECT /*+ USE_NL(T11 T12 T13 T14 T15 T16 T17 T18) */ T11.C1 , T11.C2 , 
    T12.C1 , T12.C2 , T13.C1 , T13.C2 , T14.C1 , T14.C2 , T15.C1 , T15.C2 , 
    T16.C1 , T16.C2 , T17.C1 , T17.C2 , T18.C1 , T18.C2  FROM T1 T11 , T1 
    T12 , T1 T13 , T1 T14 , T1 T15 , T1 T16 , T1 T17 , T1 T18 WHERE     
    T11.C1=T12.C1    AND T11.C1=T13.C1    AND T11.C1=T14.C1    AND 
    T11.C1=T15.C1    AND T11.C1=T16.C1    AND T11.C1=T17.C1    AND 
    T11.C1=T18.C1    AND T11.C1 BETWEEN 'A 0000000' AND 'A 0200000'
     
    Plan hash value: 97354458
     
    --------------------------------------------------------------------------------------------------------------
    | Id  | Operation                           | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
    --------------------------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT                    |              |      1 |        |    200K|00:00:05.20 |    1671K|
    |   1 |  NESTED LOOPS                       |              |      1 |        |    200K|00:00:05.20 |    1671K|
    |   2 |   NESTED LOOPS                      |              |      1 |    200K|    200K|00:00:04.80 |    1471K|
    |   3 |    NESTED LOOPS                     |              |      1 |    200K|    200K|00:00:04.60 |    1435K|
    |   4 |     NESTED LOOPS                    |              |      1 |    200K|    200K|00:00:03.80 |    1203K|
    |   5 |      NESTED LOOPS                   |              |      1 |    200K|    200K|00:00:03.20 |     968K|
    |   6 |       NESTED LOOPS                  |              |      1 |    200K|    200K|00:00:02.40 |     733K|
    |   7 |        NESTED LOOPS                 |              |      1 |    200K|    200K|00:00:01.60 |     499K|
    |   8 |         NESTED LOOPS                |              |      1 |    200K|    200K|00:00:01.00 |     241K|
    |*  9 |          TABLE ACCESS FULL          | T1           |      1 |    200K|    200K|00:00:00.01 |    5210 |
    |  10 |          TABLE ACCESS BY INDEX ROWID| T1           |    200K|      1 |    200K|00:00:00.84 |     236K|
    |* 11 |           INDEX UNIQUE SCAN         | SYS_C0015455 |    200K|      1 |    200K|00:00:00.31 |   36029 |
    |  12 |         TABLE ACCESS BY INDEX ROWID | T1           |    200K|      1 |    200K|00:00:00.56 |     257K|
    |* 13 |          INDEX UNIQUE SCAN          | SYS_C0015455 |    200K|      1 |    200K|00:00:00.34 |   57913 |
    |  14 |        TABLE ACCESS BY INDEX ROWID  | T1           |    200K|      1 |    200K|00:00:00.56 |     234K|
    |* 15 |         INDEX UNIQUE SCAN           | SYS_C0015455 |    200K|      1 |    200K|00:00:00.28 |   34333 |
    |  16 |       TABLE ACCESS BY INDEX ROWID   | T1           |    200K|      1 |    200K|00:00:00.62 |     235K|
    |* 17 |        INDEX UNIQUE SCAN            | SYS_C0015455 |    200K|      1 |    200K|00:00:00.34 |   35289 |
    |  18 |      TABLE ACCESS BY INDEX ROWID    | T1           |    200K|      1 |    200K|00:00:00.50 |     234K|
    |* 19 |       INDEX UNIQUE SCAN             | SYS_C0015455 |    200K|      1 |    200K|00:00:00.34 |   34242 |
    |  20 |     TABLE ACCESS BY INDEX ROWID     | T1           |    200K|      1 |    200K|00:00:00.56 |     232K|
    |* 21 |      INDEX UNIQUE SCAN              | SYS_C0015455 |    200K|      1 |    200K|00:00:00.31 |   32572 |
    |* 22 |    INDEX UNIQUE SCAN                | SYS_C0015455 |    200K|      1 |    200K|00:00:00.12 |   35690 |
    |  23 |   TABLE ACCESS BY INDEX ROWID       | T1           |    200K|      1 |    200K|00:00:00.22 |     200K|
    --------------------------------------------------------------------------------------------------------------
     
    Predicate Information (identified by operation id):
    ---------------------------------------------------
       9 - filter(("T11"."C1">='A 0000000' AND "T11"."C1"<='A 0200000'))
      11 - access("T11"."C1"="T12"."C1")
           filter(("T12"."C1">='A 0000000' AND "T12"."C1"<='A 0200000'))
      13 - access("T11"."C1"="T13"."C1")
           filter(("T13"."C1">='A 0000000' AND "T13"."C1"<='A 0200000'))
      15 - access("T11"."C1"="T14"."C1")
           filter(("T14"."C1">='A 0000000' AND "T14"."C1"<='A 0200000'))
      17 - access("T11"."C1"="T15"."C1")
           filter(("T15"."C1">='A 0000000' AND "T15"."C1"<='A 0200000'))
      19 - access("T11"."C1"="T16"."C1")
           filter(("T16"."C1">='A 0000000' AND "T16"."C1"<='A 0200000'))
      21 - access("T11"."C1"="T17"."C1")
           filter(("T17"."C1">='A 0000000' AND "T17"."C1"<='A 0200000'))
      22 - access("T11"."C1"="T18"."C1")
           filter(("T18"."C1">='A 0000000' AND "T18"."C1"<='A 0200000'))
    With 8 competing operating system processes on a single CPU box:
    SQL_ID  9tnwsdrsbundx, child number 1
    -------------------------------------
    SELECT /*+ USE_NL(T11 T12 T13 T14 T15 T16 T17 T18) */ T11.C1 , T11.C2 , 
    T12.C1 , T12.C2 , T13.C1 , T13.C2 , T14.C1 , T14.C2 , T15.C1 , T15.C2 , 
    T16.C1 , T16.C2 , T17.C1 , T17.C2 , T18.C1 , T18.C2  FROM T1 T11 , T1 
    T12 , T1 T13 , T1 T14 , T1 T15 , T1 T16 , T1 T17 , T1 T18 WHERE     
    T11.C1=T12.C1    AND T11.C1=T13.C1    AND T11.C1=T14.C1    AND 
    T11.C1=T15.C1    AND T11.C1=T16.C1    AND T11.C1=T17.C1    AND 
    T11.C1=T18.C1    AND T11.C1 BETWEEN 'A 0000000' AND 'A 0200000'
     
    Plan hash value: 97354458
     
    --------------------------------------------------------------------------------------------------------------
    | Id  | Operation                           | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
    --------------------------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT                    |              |      1 |        |    200K|00:00:08.63 |    1671K|
    |   1 |  NESTED LOOPS                       |              |      1 |        |    200K|00:00:08.63 |    1671K|
    |   2 |   NESTED LOOPS                      |              |      1 |    200K|    200K|00:00:08.03 |    1471K|
    |   3 |    NESTED LOOPS                     |              |      1 |    200K|    200K|00:00:07.43 |    1435K|
    |   4 |     NESTED LOOPS                    |              |      1 |    200K|    200K|00:00:05.83 |    1203K|
    |   5 |      NESTED LOOPS                   |              |      1 |    200K|    200K|00:00:04.43 |     968K|
    |   6 |       NESTED LOOPS                  |              |      1 |    200K|    200K|00:00:03.43 |     733K|
    |   7 |        NESTED LOOPS                 |              |      1 |    200K|    200K|00:00:02.40 |     499K|
    |   8 |         NESTED LOOPS                |              |      1 |    200K|    200K|00:00:01.00 |     241K|
    |*  9 |          TABLE ACCESS FULL          | T1           |      1 |    200K|    200K|00:00:00.01 |    5210 |
    |  10 |          TABLE ACCESS BY INDEX ROWID| T1           |    200K|      1 |    200K|00:00:00.78 |     236K|
    |* 11 |           INDEX UNIQUE SCAN         | SYS_C0015455 |    200K|      1 |    200K|00:00:00.41 |   36029 |
    |  12 |         TABLE ACCESS BY INDEX ROWID | T1           |    200K|      1 |    200K|00:00:01.06 |     257K|
    |* 13 |          INDEX UNIQUE SCAN          | SYS_C0015455 |    200K|      1 |    200K|00:00:00.69 |   57913 |
    |  14 |        TABLE ACCESS BY INDEX ROWID  | T1           |    200K|      1 |    200K|00:00:00.91 |     234K|
    |* 15 |         INDEX UNIQUE SCAN           | SYS_C0015455 |    200K|      1 |    200K|00:00:00.28 |   34333 |
    |  16 |       TABLE ACCESS BY INDEX ROWID   | T1           |    200K|      1 |    200K|00:00:00.88 |     235K|
    |* 17 |        INDEX UNIQUE SCAN            | SYS_C0015455 |    200K|      1 |    200K|00:00:00.44 |   35289 |
    |  18 |      TABLE ACCESS BY INDEX ROWID    | T1           |    200K|      1 |    200K|00:00:01.03 |     234K|
    |* 19 |       INDEX UNIQUE SCAN             | SYS_C0015455 |    200K|      1 |    200K|00:00:00.47 |   34242 |
    |  20 |     TABLE ACCESS BY INDEX ROWID     | T1           |    200K|      1 |    200K|00:00:01.41 |     232K|
    |* 21 |      INDEX UNIQUE SCAN              | SYS_C0015455 |    200K|      1 |    200K|00:00:00.56 |   32572 |
    |* 22 |    INDEX UNIQUE SCAN                | SYS_C0015455 |    200K|      1 |    200K|00:00:00.50 |   35690 |
    |  23 |   TABLE ACCESS BY INDEX ROWID       | T1           |    200K|      1 |    200K|00:00:00.47 |     200K|
    --------------------------------------------------------------------------------------------------------------
     
    Predicate Information (identified by operation id):
    ---------------------------------------------------
       9 - filter(("T11"."C1">='A 0000000' AND "T11"."C1"<='A 0200000'))
      11 - access("T11"."C1"="T12"."C1")
           filter(("T12"."C1">='A 0000000' AND "T12"."C1"<='A 0200000'))
      13 - access("T11"."C1"="T13"."C1")
           filter(("T13"."C1">='A 0000000' AND "T13"."C1"<='A 0200000'))
      15 - access("T11"."C1"="T14"."C1")
           filter(("T14"."C1">='A 0000000' AND "T14"."C1"<='A 0200000'))
      17 - access("T11"."C1"="T15"."C1")
           filter(("T15"."C1">='A 0000000' AND "T15"."C1"<='A 0200000'))
      19 - access("T11"."C1"="T16"."C1")
           filter(("T16"."C1">='A 0000000' AND "T16"."C1"<='A 0200000'))
      21 - access("T11"."C1"="T17"."C1")
           filter(("T17"."C1">='A 0000000' AND "T17"."C1"<='A 0200000'))
      22 - access("T11"."C1"="T18"."C1")
           filter(("T18"."C1">='A 0000000' AND "T18"."C1"<='A 0200000'))
    With no other load, the TKPROF output:
    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           0
    Fetch     2001      5.57       5.87          0    1671278          0      200000
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total     2003      5.57       5.87          0    1671278          0      200000
     
    Misses in library cache during parse: 0
    Optimizer mode: ALL_ROWS
    Parsing user id: 60  
     
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                    2001        0.00          0.00
      SQL*Net more data to client                  8001        0.00          0.08
      SQL*Net message from client                  2001       16.34         18.34
    Note that another SQL statement was executed immediately after the above SQL statement, so I cannot explain the 16.34 second wait on SQL*Net message from client - see below.

    With 8 competing operating system processes on a single CPU box, the TKPROF output:
    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           0
    Fetch     2001      9.70       9.84          0    1671278          0      200000
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total     2003      9.70       9.84          0    1671278          0      200000
     
    Misses in library cache during parse: 0
    Optimizer mode: ALL_ROWS
    Parsing user id: 60  
     
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                    2001        0.00          0.00
      SQL*Net more data to client                  8001        0.00          0.11
      SQL*Net message from client                  2001       16.14         18.68
    On the Windows platform, it appears that time spent in the run queue might be counted as CPU time based on the above, but there might be another explanation.

    With no other load, the timestamps from the runs:
    Cursor 8   Ver 1   Parse at 0.000000 (Parse to Parse 0.000000),CPU Time 0.000000,Elapsed Time 0.000000,Rows Affected 0,Blks from Buff 0,Blks from Disk 0,Goal=ALL_ROWS
    Cursor 8   Ver 1 Execute at 0.000000 (Parse to Exec  0.000000),CPU Time 0.000000,Elapsed Time 0.000000,Rows Affected 0,Blks from Buff 0,Blks from Disk 0,
    Cursor 8   Ver 1            0.002193  0.000002   SQL*Net message to client
    Cursor 8   Ver 1            0.002527  0.000023   SQL*Net more data to client
    Cursor 8   Ver 1            0.003162  0.000012   SQL*Net more data to client
    Cursor 8   Ver 1            0.003691  0.000010   SQL*Net more data to client
    Cursor 8   Ver 1            0.004246  0.000009   SQL*Net more data to client
    Cursor 8   Ver 1            0.004799  0.000010   SQL*Net more data to client
    Cursor 8   Ver 1   Fetch at 0.000000 (Parse to Fetch 0.000000),CPU Time 0.000000,Elapsed Time 0.000000,Rows Retrievd 100,Blks from Buff 778,Blks from Disk 0
    Cursor 8   Ver 1            0.008852  0.003958   SQL*Net message from client
    Cursor 8   Ver 1            0.008929  0.000001   SQL*Net message to client
    Cursor 8   Ver 1            0.009435  0.000011   SQL*Net more data to client
    Cursor 8   Ver 1            0.009977  0.000009   SQL*Net more data to client
    Cursor 8   Ver 1            0.010501  0.000010   SQL*Net more data to client
    Cursor 8   Ver 1            0.011046  0.000009   SQL*Net more data to client
    Cursor 8   Ver 1   Fetch at 0.000000 (Parse to Fetch 0.000000),CPU Time 0.000000,Elapsed Time 0.000000,Rows Retrievd 100,Blks from Buff 710,Blks from Disk 0
    Cursor 8   Ver 1            0.012013  0.000791   SQL*Net message from client
    Cursor 8   Ver 1            0.012137  0.000001   SQL*Net message to client
    Cursor 8   Ver 1            0.012648  0.000015   SQL*Net more data to client
    Cursor 8   Ver 1            0.013190  0.000010   SQL*Net more data to client
    Cursor 8   Ver 1            0.013712  0.000010   SQL*Net more data to client
    Cursor 8   Ver 1            0.014303  0.000011   SQL*Net more data to client
    Cursor 8   Ver 1   Fetch at 0.011909 (Parse to Fetch 0.011909),CPU Time 0.000000,Elapsed Time 0.000000,Rows Retrievd 100,Blks from Buff 709,Blks from Disk 0
    Cursor 8   Ver 1            0.015256  0.000769   SQL*Net message from client
    Cursor 8   Ver 1            0.015329  0.000001   SQL*Net message to client
    Cursor 8   Ver 1            0.015977  0.000012   SQL*Net more data to client
    Cursor 8   Ver 1            0.016525  0.000010   SQL*Net more data to client
    Cursor 8   Ver 1            0.017050  0.000010   SQL*Net more data to client
    Cursor 8   Ver 1            0.017598  0.000010   SQL*Net more data to client
    Cursor 8   Ver 1   Fetch at 0.011909 (Parse to Fetch 0.011909),CPU Time 0.000000,Elapsed Time 0.000000,Rows Retrievd 100,Blks from Buff 776,Blks from Disk 0
    Cursor 8   Ver 1            0.018508  0.000733   SQL*Net message from client
    Cursor 8   Ver 1            0.018577  0.000001   SQL*Net message to client
    Cursor 8   Ver 1            0.019086  0.000010   SQL*Net more data to client
    Cursor 8   Ver 1            0.019632  0.000010   SQL*Net more data to client
    Cursor 8   Ver 1            0.020156  0.000010   SQL*Net more data to client
    Cursor 8   Ver 1            0.020700  0.000009   SQL*Net more data to client
    Cursor 8   Ver 1   Fetch at 0.011909 (Parse to Fetch 0.011909),CPU Time 0.000000,Elapsed Time 0.000000,Rows Retrievd 100,Blks from Buff 710,Blks from Disk 0
    ...
    Cursor 8   Ver 1   Fetch at 7.418069 (Parse to Fetch 7.418069),CPU Time 0.000000,Elapsed Time 0.000000,Rows Retrievd 100,Blks from Buff 712,Blks from Disk 0
    Cursor 8   Ver 1            7.439808  0.000795   SQL*Net message from client
    Cursor 8   Ver 1            7.439876  0.000001   SQL*Net message to client
    Cursor 8   Ver 1            7.440395  0.000011   SQL*Net more data to client
    Cursor 8   Ver 1            7.440929  0.000010   SQL*Net more data to client
    Cursor 8   Ver 1            7.441470  0.000010   SQL*Net more data to client
    Cursor 8   Ver 1            7.442113  0.000010   SQL*Net more data to client
    Cursor 8   Ver 1   Fetch at 7.418069 (Parse to Fetch 7.418069),CPU Time 0.000000,Elapsed Time 0.000000,Rows Retrievd 100,Blks from Buff 782,Blks from Disk 0
    Cursor 8   Ver 1            7.443608  0.001325   SQL*Net message from client
    Cursor 8   Ver 1            7.443677  0.000001   SQL*Net message to client
    Cursor 8   Ver 1            7.444180  0.000011   SQL*Net more data to client
    Cursor 8   Ver 1            7.444726  0.000010   SQL*Net more data to client
    Cursor 8   Ver 1            7.445236  0.000010   SQL*Net more data to client
    Cursor 8   Ver 1            7.445770  0.000010   SQL*Net more data to client
    Cursor 8   Ver 1   Fetch at 7.418069 (Parse to Fetch 7.418069),CPU Time 0.000000,Elapsed Time 0.000000,Rows Retrievd 100,Blks from Buff 712,Blks from Disk 0
    Cursor 8   Ver 1            7.446706  0.000763   SQL*Net message from client
    Cursor 8   Ver 1   Fetch at 7.418069 (Parse to Fetch 7.418069),CPU Time 0.000000,Elapsed Time 0.000000,Rows Retrievd 0,Blks from Buff 1,Blks from Disk 0
    Cursor 8   Ver 1            7.446802  0.000001   SQL*Net message to client
    Cursor 8   Ver 1            23.793101  16.346278   SQL*Net message from client
    ----------------------------------------------------------------------------------
    Cursor 3   Ver 1   Parse at 23.792869  (23.792869)
    With 8 competing operating system processes on a single CPU box, the timestamps:
    Cursor 9   Ver 1   Parse at 0.000000 (Parse to Parse 0.000000),CPU Time 0.000000,Elapsed Time 0.000000,Rows Affected 0,Blks from Buff 0,Blks from Disk 0,Goal=ALL_ROWS
    Cursor 9   Ver 1 Execute at 0.000000 (Parse to Exec  0.000000),CPU Time 0.000000,Elapsed Time 0.000000,Rows Affected 0,Blks from Buff 0,Blks from Disk 0,
    Cursor 9   Ver 1            0.002964  0.000002   SQL*Net message to client
    Cursor 9   Ver 1            0.003441  0.000027   SQL*Net more data to client
    Cursor 9   Ver 1            0.004569  0.000016   SQL*Net more data to client
    Cursor 9   Ver 1            0.005553  0.000013   SQL*Net more data to client
    Cursor 9   Ver 1            0.006582  0.000013   SQL*Net more data to client
    Cursor 9   Ver 1            0.007653  0.000016   SQL*Net more data to client
    Cursor 9   Ver 1   Fetch at 0.000000 (Parse to Fetch 0.000000),CPU Time 0.015625,Elapsed Time 0.000000,Rows Retrievd 100,Blks from Buff 778,Blks from Disk 0
    Cursor 9   Ver 1            0.022648  0.014850   SQL*Net message from client
    Cursor 9   Ver 1            0.022851  0.000002   SQL*Net message to client
    Cursor 9   Ver 1            0.023870  0.000028   SQL*Net more data to client
    Cursor 9   Ver 1            0.024898  0.000018   SQL*Net more data to client
    Cursor 9   Ver 1            0.025865  0.000014   SQL*Net more data to client
    Cursor 9   Ver 1            0.026886  0.000015   SQL*Net more data to client
    Cursor 9   Ver 1   Fetch at 0.022585 (Parse to Fetch 0.022585),CPU Time 0.000000,Elapsed Time 0.000000,Rows Retrievd 100,Blks from Buff 710,Blks from Disk 0
    Cursor 9   Ver 1            0.038245  0.011067   SQL*Net message from client
    Cursor 9   Ver 1            0.038388  0.000002   SQL*Net message to client
    Cursor 9   Ver 1            0.039361  0.000019   SQL*Net more data to client
    Cursor 9   Ver 1            0.040372  0.000013   SQL*Net more data to client
    Cursor 9   Ver 1            0.041448  0.000015   SQL*Net more data to client
    Cursor 9   Ver 1            0.042454  0.000012   SQL*Net more data to client
    Cursor 9   Ver 1   Fetch at 0.022585 (Parse to Fetch 0.022585),CPU Time 0.000000,Elapsed Time 0.000000,Rows Retrievd 100,Blks from Buff 709,Blks from Disk 0
    Cursor 9   Ver 1            0.043576  0.000833   SQL*Net message from client
    Cursor 9   Ver 1            0.043690  0.000002   SQL*Net message to client
    Cursor 9   Ver 1            0.044845  0.000016   SQL*Net more data to client
    Cursor 9   Ver 1            0.045863  0.000013   SQL*Net more data to client
    Cursor 9   Ver 1            0.046837  0.000012   SQL*Net more data to client
    Cursor 9   Ver 1            0.047855  0.000012   SQL*Net more data to client
    Cursor 9   Ver 1   Fetch at 0.022585 (Parse to Fetch 0.022585),CPU Time 0.000000,Elapsed Time 0.000000,Rows Retrievd 100,Blks from Buff 776,Blks from Disk 0
    Cursor 9   Ver 1            0.049368  0.001228   SQL*Net message from client
    Cursor 9   Ver 1            0.049475  0.000002   SQL*Net message to client
    Cursor 9   Ver 1            0.050446  0.000014   SQL*Net more data to client
    Cursor 9   Ver 1            0.051462  0.000012   SQL*Net more data to client
    Cursor 9   Ver 1            0.052429  0.000012   SQL*Net more data to client
    Cursor 9   Ver 1            0.053438  0.000013   SQL*Net more data to client
    Cursor 9   Ver 1   Fetch at 0.022585 (Parse to Fetch 0.022585),CPU Time 0.000000,Elapsed Time 0.000000,Rows Retrievd 100,Blks from Buff 710,Blks from Disk 0
    ...
    Cursor 9   Ver 1   Fetch at 12.147437 (Parse to Fetch 12.147437),CPU Time 0.000000,Elapsed Time 0.000000,Rows Retrievd 100,Blks from Buff 712,Blks from Disk 0
    Cursor 9   Ver 1            12.178699  0.015796   SQL*Net message from client
    Cursor 9   Ver 1            12.178845  0.000002   SQL*Net message to client
    Cursor 9   Ver 1            12.179827  0.000019   SQL*Net more data to client
    Cursor 9   Ver 1            12.180830  0.000013   SQL*Net more data to client
    Cursor 9   Ver 1            12.181839  0.000013   SQL*Net more data to client
    Cursor 9   Ver 1            12.182996  0.000012   SQL*Net more data to client
    Cursor 9   Ver 1   Fetch at 12.178685 (Parse to Fetch 12.178685),CPU Time 0.000000,Elapsed Time 0.000000,Rows Retrievd 100,Blks from Buff 782,Blks from Disk 0
    Cursor 9   Ver 1            12.184158  0.000874   SQL*Net message from client
    Cursor 9   Ver 1            12.184266  0.000001   SQL*Net message to client
    Cursor 9   Ver 1            12.185229  0.000016   SQL*Net more data to client
    Cursor 9   Ver 1            12.186243  0.000012   SQL*Net more data to client
    Cursor 9   Ver 1            12.187201  0.000013   SQL*Net more data to client
    Cursor 9   Ver 1            12.188200  0.000011   SQL*Net more data to client
    Cursor 9   Ver 1   Fetch at 12.178685 (Parse to Fetch 12.178685),CPU Time 0.000000,Elapsed Time 0.000000,Rows Retrievd 100,Blks from Buff 712,Blks from Disk 0
    Cursor 9   Ver 1            12.189289  0.000810   SQL*Net message from client
    Cursor 9   Ver 1   Fetch at 12.178685 (Parse to Fetch 12.178685),CPU Time 0.000000,Elapsed Time 0.000000,Rows Retrievd 0,Blks from Buff 1,Blks from Disk 0
    Cursor 9   Ver 1            12.189419  0.000001   SQL*Net message to client
    Cursor 9   Ver 1            28.336122  16.146674   SQL*Net message from client
    ----------------------------------------------------------------------------------
    Cursor 7   Ver 1   Parse at 28.334740  (28.334740)
    Charles Hooper
    Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
    http://hoopercharles.wordpress.com/
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 3. Re: cpu in tkprof (or 10046 raw file)
    649748 Newbie
    Currently Being Moderated
    Hi Hooper,

    Thanks for your test. In theory, if there is no way to get the exact time on cpu from OS level, then oracle also can't get the exact time on cpu. For OS not supporting microstate accouting, then I think the code is like

    1: get the current time
    2: run code on cpu
    3: get the current time, and minus it by the value from step 1 to get the time on cpu. But if step 2 experiences latency, then the calculated cpu time will be larger than reality.

    On solaris, it might get the right cpu time as miscrostate accounting is supported in solaris, in theory oracle could get the accurate cpu time If it uses data from miscrostate accounting.

Legend

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