RE: Method R and CPU Time
- From: "MacGregor, Ian A." <ian@xxxxxxxxxxxxxxxxx>
- To: "'oracle-l@xxxxxxxxxxxxx'" <oracle-l@xxxxxxxxxxxxx>
- Date: Tue, 6 Jul 2004 17:50:28 -0700
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
----------
0
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@xxxxxxxxxxxxxxxxx
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@xxxxxxxxxx]
Sent: Tuesday, July 06, 2004 1:58 PM
To: oracle-l@xxxxxxxxxxxxx
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@xxxxxxxxxxxxx
put 'unsubscribe' in the subject line.
--
Archives are at //www.freelists.org/archives/oracle-l/
FAQ is at //www.freelists.org/help/fom-serve/cache/1.html
-----------------------------------------------------------------
Other related posts:
