RE: Method R and CPU Time

From: MacGregor, Ian A. <ian_at_slac.stanford.edu>
Date: Tue, 6 Jul 2004 17:50:28 -0700
Message-ID: <26E3EC48949D134C94A1574B2C89466113A96F@exchange2.slac.stanford.edu>

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

OPERA CPU_TIME ELAPSED_TIME
----- ---------- ------------

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;

MISSES

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
ian_at_SLAC.Stanford.edu

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 [mailto:cary.millsap_at_hotsos.com] Sent: Tuesday, July 06, 2004 1:58 PM
To: oracle-l_at_freelists.org
Subject: RE: Method R and CPU Time

Ian,

Some timed events like "SQL*Net message from client" (and "...to 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: http://www.orafaq.com

To unsubscribe send email to: oracle-l-request_at_freelists.org put 'unsubscribe' in the subject line.

--
Archives are at http://www.freelists.org/archives/oracle-l/
FAQ is at http://www.freelists.org/help/fom-serve/cache/1.html


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

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