| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
 |
 | |||
| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
|
| |||
Home -> Community -> Mailing Lists -> Oracle-L -> RE: Method R and CPU Time
I wouldn't consider 8x8KB reads to be very large either. The times when =
I've
encountered a big double-counting problem (for example, e=3D10, c=3D8,
sum(ela)=3D8) have been for reads with p3=3D64 or p3=3D128 blocks--stuff =
like
that...
Can you show me the trace data for a single FETCH call (that is, the =
FETCH
#k line itself and all the WAIT #k lines that precede that FETCH line)?
Cary Millsap
Hotsos Enterprises, Ltd.
http://www.hotsos.com
* Nullius in verba *
Upcoming events:
- Performance Diagnosis 101: 6/22 Pittsburgh, 7/20 Cleveland, 8/10 =
Boston
- SQL Optimization 101: 5/24 San Diego, 6/14 Chicago, 6/28 Denver - Hotsos Symposium 2005: March 6-10 Dallas - Visit www.hotsos.com for schedule details...
-----Original Message-----
From: oracle-l-bounce_at_freelists.org =
[mailto:oracle-l-bounce_at_freelists.org]
On Behalf Of MacGregor, Ian A.
Sent: Tuesday, July 06, 2004 8:08 PM
To: 'oracle-l_at_freelists.org'
Subject: RE: Method R and CPU Time
I have re-read Chaper 7 especially pg 153-154, a section entitled, "CPU
Consumption Double-Counting". I expected the double counting to be
negligible. The text does say USUALLY negligible. Thanks also for the
multi-block read information. I did not notice this discrepancy on =
queries
dominated by single-block read events. The multi-block reads in the
example are not large, each is 8, 8k blocks or less, with very few or =
less.
I don't consider these to be large reads.=20
Ian =20
-----Original Message-----
From: Cary Millsap [mailto:cary.millsap_at_hotsos.com]=20
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" =
=3D
and several others) are not double-counted within any "e" value. In the =
=3D
book, I call these "between-call events". Other events that represent =
work =3D
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 =
=3D
"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). =
=3D 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 =3D
syscall spends consuming CPU is double-counted both in "c" for the =
dbcall
and =3D "ela"
for the read. This breaks the relationship e \approx c + \Sum ela. The
larger the I/O size, the bigger the breakage.=3D20
Pictures in the book.
Cary Millsap
Hotsos Enterprises, Ltd.
http://www.hotsos.com
* Nullius in verba *
Upcoming events:
- Performance Diagnosis 101: 6/22 Pittsburgh, 7/20 Cleveland, 8/10 =3D =
Boston
- SQL Optimization 101: 5/24 San Diego, 6/14 Chicago, 6/28 Denver - Hotsos Symposium 2005: March 6-10 Dallas - Visit www.hotsos.com for schedule details...
-----Original Message-----
From: oracle-l-bounce_at_freelists.org =3D
[mailto:oracle-l-bounce_at_freelists.org]
On Behalf Of MacGregor, Ian A.
Sent: Tuesday, July 06, 2004 3:48 PM
To: 'oracle-l_at_freelists.org'
Subject: RE: Method R and CPU Time
Thank you very much for responding. I decided to do away with tkprof =
=3D and
calculate the nubers myself. I chose another example where the =3D =
statement
is taking a longer time to run
Here is what I got from using the tkprof method
RUN_DATE TRACE_ID EVENT =3DWAITS
-------------------------------------------------------------------------=
--- ------------------------------------ 26-JUN-2004 03:07 nlco_ora_2991 db file sequential read =Received on Tue Jul 06 2004 - 22:24:02 CDT
=3D
1165 4.9 170.87 142.1 26-JUN-2004 03:07 db file scattered read =
=3D
6756 147.41 170.87 142.1 26-JUN-2004 03:07 SQL*Net message from client =
=3D
550 1.46 170.87 142.1 *************** =3D ---------- ---------- sum =
=3D
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=3D3D0, the statement had already been parsed = before =3D this run.=3D20 SQL> select distinct misses from raw_ops_external; MISSES ---------- 0 grep -i dep nlco_ora_2991.trc | wc 604 1428 44874 grep -i dep=3D3D0 nlco_ora_2991.trc | wc 604 1428 44874 grep -i dep=3D3D1 nlco_ora_2991.trc | wc 0 0 0 What I did was to "grep -I wait" and write the results to a file. I =
=3D
then again used the external table feature and used sum and compute to =
=3D
produce the report. I then did the same thing with the parse, exec, and fetch lines. The report agrees favorably with the tkprof output.=3D20 Here are the external table definitions SQL> describe raw_waits_external Name Null? Type ----------------------------------------- -------- ---------------------------- TRACE_ID VARCHAR2(15) EVENT VARCHAR2(30) MICROSECONDS NUMBER(9) P1 NUMBER(15) P2 NUMBER(10) P3 NUMBER(2)=3D20 SQL> describe raw_ops_external Name Null? Type ----------------------------------------- -------- ---------------------------- TRACE_ID VARCHAR2(15) OPERATION VARCHAR2(5) CPU NUMBER(10) ELAPSED NUMBER(10) PHYSICAL_R NUMBER(6) CONSISTENT_R NUMBER(6) CURRENT_R NUMBER(6) MISSES NUMBER(2) ROW_COUNT NUMBER(3) DEPTH NUMBER(2) OPT_GOAL NUMBER(2) TIM NUMBER(15) Perhaps I'm making the same mistake as tkprof as our figures agree. =3D Perhaps I have to throw out some of the lines from the trace files = despite all depths being =3D3D 0 and there being no library cache misses. Any =
=3D
suggestion as to where the double-counting is occuring. I'm ready to change the premise that one cannot always separate time =3D = 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 =3D = 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 -----Original Message----- From: Cary Millsap [mailto:cary.millsap_at_hotsos.com]=3D20 Sent: Tuesday, July 06, 2004 9:23 AM To: oracle-l_at_freelists.org Subject: RE: Method R and CPU Time Tkprof double-counts /horribly/. It begins with how it handles the =3D3D so-called "idle events." Cary Millsap Hotsos Enterprises, Ltd. http://www.hotsos.com * Nullius in verba * Upcoming events: - Performance Diagnosis 101: 6/22 Pittsburgh, 7/20 Cleveland, 8/10 =3D3D =
=3D
Boston - SQL Optimization 101: 5/24 San Diego, 6/14 Chicago, 6/28 Denver - Hotsos Symposium 2005: March 6-10 Dallas - Visit www.hotsos.com for schedule details... -----Original Message----- From: oracle-l-bounce_at_freelists.org =3D3D [mailto:oracle-l-bounce_at_freelists.org] On Behalf Of MacGregor, Ian A. Sent: Saturday, July 03, 2004 2:31 PM To: 'oracle-l_at_freelists.org' Subject: RE: Method R and CPU Time Thanks, these figures are from tkprof on a 9.2.0.4 database. I used =
=3D =3D3D
grep to extract the totals for all non-recursive SQL statements and then =
=3D
=3D3D turned
that output into an external table. I did the same thing with the =
=3D3D
waits. I had earlier checked the figures tkprof provides vs. the raw trace file =
=3D
=3D3D for the same statement run once and found they agreed. I have not =
=3D
summed =3D3D the waits from the raw trace file upon which tkprof was = run, but the CPU =3D and elapsed times do agree between the raw trace file and = the tkprof output. As CPU_SECS + Wait_SECS > 1.5 * Elapsed_SECS, it appears the =3D3D double-counting is not always incidental, but can be significant when =
=3D
there are db file =3D3D I/O waits involved. If this is true, can one = really use method R to =3D3D evaluate how a hardware upgrade will affect = performance. Remember, the figures are from tkprof which Cary states can get things wrong, and the wait times totals have not been confirmed as accurate =
=3D3D =3D
from the raw trace data; hence, the question is premature. Has anyone = had difficulty separating time spent waiting for file i/o vs. CPU time? Ian MacGregor Stanford Linear Accelerator Center ian_at_SLAC.Stanford.edu =3D3D20 -----Original Message----- From: Jonathan Lewis [mailto:jonathan_at_jlcomp.demon.co.uk]=3D3D20 Sent: Saturday, July 03, 2004 3:03 AM To: oracle-l_at_freelists.org Subject: Re: Method R and CPU Time Notes in-line. Regards Jonathan Lewis http://www.jlcomp.demon.co.uk http://www.jlcomp.demon.co.uk/faq/ind_faq.html The Co-operative Oracle Users' FAQ http://www.jlcomp.demon.co.uk/seminar.html Optimising Oracle Seminar - schedule updated May 1st ----- Original Message ----- From: "MacGregor, Ian A." <ian_at_slac.stanford.edu> To: <oracle-l_at_freelists.org> Sent: Friday, July 02, 2004 3:42 PM Subject: RE: Method R and CPU Time The figures represent totals from running the same statement 10 =3D3D =
=3D
different times with different bind variables, that is on average the elapsed time =3D =3D3D is 1.429 seconds per statement execution. Also because the report is =
=3D3D =3D
based on 10 runs of a statement any discrepancies in the figuring of e, = ela,
=3D =3D3D or c are magnified.
[jpl] Not necessarily, though you may know it to be true in your case. [jpl] In the general case, 10 runs would be more likely to flatten out anomalies [jpl] minimise descrepancies. The statements ran starting at 12:05 PM on Jun 25. Statspack from noon =
=3D
=3D3D to
12:15 reported 630 seconds of CPU time. Again there are four CPU's, =
=3D =3D3D
the machine was not overloaded. My original question had to do as to why "sum(ela)" + "c" was over 1.5 times as high as "e", and whether for a statement running on a single =
=3D =3D3D
CPU one needed to divide the reported CPU time by the number of = processors =3D
=3D3D on the machine just as one would when looking at total CPU time =
across the entire machine. If I do that, then ela + c < e, but the error is much =
=3D
=3D3D
much less. [jpl] Without knowing what tools you are using to produce [jpl] the =3D numbers, and where they are coming from, and what [jpl] actually is happening in =3D the code, it is not possible to give [jpl] a guaranteed answer to that =3D question. But if you are just [jpl] reading v$mystat and v$session_event for the session, and [jpl] parts of the query are parallelised, you need to know that [jpl] PX slave stats are summed back to the QC, but PX slave [jpl] waits are not. So any attempt to add ela to c to get [jpl] elapsed time would be misguided. [jpl] On the other hand, you didn't mention any PX Deq wait [jpl] time, =
=3D
and I assumed from the reference to ela and c that [jpl] you are = processing
=3D a
10046 trace file - so the simple answer [jpl] to your original question =
=3D is
no - you don't need to divide [jpl] the c figure by the number of processors. There are things outside of disk waits and CPU times which need to be researched. Such as why submit 10 different requests for 10 different signals. The requests themselves union a daily partioned table with indexes and a non-indexed live table holding a single calendar days =
=3D3D =3D
worth of data partitioned every 10 minutes. The non-indexed table is = the one reporting the scattered read waits. The table is not indexed as it =
=3D3D
=3D needs to collect signal data in real time and is employing direct =
mode inserts =3D =3D3D via OCI. Exactly how the partition sizes were = decided, I don't know. =3D =3D3D Partition pruning is successful. No one is complaining about the above response time, but it can vary =
=3D3D
during the day due to machine load, and how much of the data is in =3D = cache, at =3D3D times reaching unacceptable levels. Faster hardware is being =
=3D
considered and =3D3D I'm trying to figure how much if any that would = help by
=3D figuring how much =3D3D time is actually spent on CPU for these =
queries vs. waits for physical I/O. Ian MacGregor Stanford Linear Accelerator Center ian_at_SLAC.Stanfod.edu ---------------------------------------------------------------- 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 ----------------------------------------------------------------- ---------------------------------------------------------------- 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 ----------------------------------------------------------------- ---------------------------------------------------------------- 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 ----------------------------------------------------------------- ---------------------------------------------------------------- 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 ----------------------------------------------------------------- ---------------------------------------------------------------- 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 ----------------------------------------------------------------- ---------------------------------------------------------------- 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 ----------------------------------------------------------------- ---------------------------------------------------------------- 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 -----------------------------------------------------------------
 |
 |