3 Replies Latest reply: Mar 16, 2010 2:34 AM by 649748 RSS

    cpu in tkprof (or 10046 raw file)

    649748
      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
          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)
            Charles Hooper
            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
              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.