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.


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@xxxxxxxxxxxxx =
[mailto:oracle-l-bounce@xxxxxxxxxxxxx]
On Behalf Of MacGregor, Ian A.
Sent: Tuesday, July 06, 2004 3:48 PM
To: 'oracle-l@xxxxxxxxxxxxx'
Subject: RE: Method R and CPU Time

Thank you very much for responding.  I decided to do away with tkprof =
and
calculate the nubers 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=3D0, the statement had already been parsed before =
this
run.=20

SQL> select distinct misses from raw_ops_external;

    MISSES
----------
         0

grep -i dep nlco_ora_2991.trc | wc
     604    1428   44874
grep -i dep=3D0 nlco_ora_2991.trc | wc
     604    1428   44874
grep -i dep=3D1 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.=20

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)=20

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.  =
Perhaps
I have to throw out some of the lines from the  trace files despite all
depths being =3D 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


-----Original Message-----
From: Cary Millsap [mailto:cary.millsap@xxxxxxxxxx]=20
Sent: Tuesday, July 06, 2004 9:23 AM
To: oracle-l@xxxxxxxxxxxxx
Subject: RE: Method R and CPU Time

Tkprof double-counts /horribly/. It begins with how it handles the =3D
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 =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@xxxxxxxxxxxxx =3D
[mailto:oracle-l-bounce@xxxxxxxxxxxxx]
On Behalf Of MacGregor, Ian A.
Sent: Saturday, July 03, 2004 2:31 PM
To: 'oracle-l@xxxxxxxxxxxxx'
Subject: RE: Method R and CPU Time

Thanks, these figures are from tkprof  on  a 9.2.0.4 database.  I used =
=3D
grep to extract the totals for all non-recursive SQL statements and then =
=3D
turned
that output into an external table.   I did the same thing with the =3D
waits.
I had earlier checked the figures tkprof provides vs. the raw trace file =
=3D
for the same statement run once and found they agreed.  I have not =
summed =3D
the waits from the raw trace file upon which tkprof was run, but the CPU =
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 =3D
double-counting is not always incidental, but can be significant when =
there
are db file =3D I/O waits involved.  If this is true, can one really use
method R to =3D 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 =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@xxxxxxxxxxxxxxxxx
 =3D20

-----Original Message-----
From: Jonathan Lewis [mailto:jonathan@xxxxxxxxxxxxxxxxxx]=3D20
Sent: Saturday, July 03, 2004 3:03 AM
To: oracle-l@xxxxxxxxxxxxx
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@xxxxxxxxxxxxxxxxx>
To: <oracle-l@xxxxxxxxxxxxx>
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 =3D =
different
times with different bind variables, that is on average the elapsed time =
=3D
is
1.429 seconds per statement execution.  Also  because the report is  =3D =
based
on 10 runs of a statement any discrepancies in the figuring of e, ela, =
=3D 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 to
12:15 reported  630 seconds of CPU time.  Again there are four CPU's, =
=3D 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 CPU
one needed to divide the reported CPU time by the number of processors =
=3D 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
much
less.

[jpl] Without knowing what tools you are using to produce [jpl] the =
numbers,
and where they are coming from, and what [jpl] actually is happening in =
the
code, it is not possible to give [jpl] a guaranteed answer to that =
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, =
and
I assumed from the reference to ela and c that [jpl] you are processing =
a
10046 trace file - so the simple answer [jpl] to your original question =
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 =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 =3D =
needs
to collect signal data in real time and is employing direct mode inserts =
=3D
via OCI.  Exactly how the partition sizes were decided, I don't know.  =
=3D
Partition pruning is successful.

No one is complaining about the above response time, but it can vary =3D
during the day due to machine load, and how much of the data is in =
cache, at
=3D times reaching unacceptable levels.  Faster hardware is being =
considered
and =3D I'm trying to figure how much if any that would  help by =
figuring how
much =3D time is actually spent on CPU for these queries vs. waits for
physical I/O.

Ian MacGregor
Stanford Linear Accelerator Center
ian@xxxxxxxxxxxxxxxx





----------------------------------------------------------------
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 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@xxxxxxxxxxxxx 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@xxxxxxxxxxxxx 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@xxxxxxxxxxxxx
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@xxxxxxxxxxxxx
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
-----------------------------------------------------------------

Other related posts: