Oracle FAQ Your Portal to the Oracle Knowledge Grid

Home -> Community -> Mailing Lists -> Oracle-L -> RE: Method R and CPU Time

RE: Method R and CPU Time

From: MacGregor, Ian A. <>
Date: Tue, 6 Jul 2004 17:50:28 -0700
Message-ID: <>

Thank you very much for responding. I decided to do away with tkprof and calculate the numbers myself. I chose another example where the statement is taking a longer time to run

Here is what I got from using the tkprof method

RUN_DATE         TRACE_ID        EVENT                               WAITS  WAIT_SECS ELAPSED_SECS   CPU_SECS

26-JUN-2004 03:07 nlco_ora_2991 db file sequential read 1165 4.9 170.87 142.1 26-JUN-2004 03:07 db file scattered read 6756 147.41 170.87 142.1 26-JUN-2004 03:07 SQL*Net message from client 550 1.46 170.87 142.1 *************** ---------- ---------- sum 8471 153.77 And here are the waits fropm the raw trace file from the above EVENT SUM(MICROSECONDS)/1000000
------------------------------ -------------------------
SQL*Net message from client 1.469555 SQL*Net message to client .002067 db file scattered read 147.412026 db file sequential read 4.906271 latch free .000009 ------------------------- sum 153.789928

And here are the elapsed tike and CPU details from the raw trace file

----- ---------- ------------

EXEC         .03      .033659
FETCH     142.07   170.824816
PARSE          0      .013718
      ---------- ------------
sum        142.1   170.872193

All cursors are at dep=0, the statement had already been parsed before this run.

SQL> select distinct misses from raw_ops_external;



grep -i dep nlco_ora_2991.trc | wc

     604 1428 44874
grep -i dep=0 nlco_ora_2991.trc | wc

     604 1428 44874
grep -i dep=1 nlco_ora_2991.trc | wc

       0 0 0

What I did was to "grep -I wait" and write the results to a file. I then again used the external table feature and used sum and compute to produce the report. I then did the same thing with the parse, exec, and fetch lines. The report agrees favorably with the tkprof output.

Perhaps I'm making the same mistake as tkprof as our figures agree. Perhaps I have to throw out some of the lines from the trace files despite all depths being = 0 and there being no library cache misses. Any suggestion as to where the double-counting is occuring.

I'm ready to change the premise that one cannot always separate time spent on CPU and time spent waiting for file I/O via method R, because the overlap between the two may be significant not incidental to an assertion.

One thing I did not mention is that the trace was done at level 12.

Ian MacGregor
Stanford Linear Accelerator Center

I believe your refering to Chapter 7 pg 153-154, a section entitled, "CPU Consumption Double Counting." I had read this before, but expected the double counting to be negligible. The text does say "usually" negligible.

Thanks for the tip about multi-block reads. I don't see the problem with db file seqeuntial read operations. The scattered reads are only 8, 8K blocks. It doesn't take much too taint the e = c + sum(ela) relationship.

-----Original Message-----

From: Cary Millsap [] Sent: Tuesday, July 06, 2004 1:58 PM
Subject: RE: Method R and CPU Time


Some timed events like "SQL*Net message from client" (and " client" = and several others) are not double-counted within any "e" value. In the = book, I call these "between-call events". Other events that represent work = taking place within the context of a dbcall (which I call "within-call events") /are/ included within an "e" value.

But there is potential for significant double-counting between "ela" and = "c" values. I don't have a copy of the book handy (Optimizing Oracle Performance), but it's described in detail there (Chapter 7, I think). = The problem will occur most prominently when your application does large multi-block reads. Basically, the issue is that the time than an I/O = syscall spends consuming CPU is double-counted both in "c" for the dbcall and = "ela" for the read. This breaks the relationship e \approx c + \Sum ela. The larger the I/O size, the bigger the breakage.=20

Pictures in the book.

Please see the official ORACLE-L FAQ:

To unsubscribe send email to: put 'unsubscribe' in the subject line.
Archives are at
FAQ is at

Received on Tue Jul 06 2004 - 19:47:27 CDT

Original text of this message