RE: Have I misinterpreted the e= and c= relationship in 10046 event trace file output?

Thanks.

-----Original Message-----
Sent: Monday, June 17, 2002 3:09 PM
To: Multiple recipients of list ORACLE-L 10046 event trace file output?

Tony,  

It's something we see often. With digital clocks, you cannot be assured that your answers are precise to tolerances smaller than one clock tick. What might be happening is this:  

c0 = cpu_time();

# time A

e0 = ela_time();

            # the event you're timing occurs here

c1 = cpu_time();

            # time B

e1 = ela_time();

c = c1 - c0;

e = e1 - e0;  

Imagine that the event you're timing consumes 0.5 clock ticks' worth of time. If the clock ticks at time A but not time B, then you'll have c=1,e=0. No matter which order a user program computes c0 and e0 (or c1 and e1), this type of problem can always occur. (It's easier to visualize if you draw the problem on a timeline.)  

It really doesn't matter, though: "0.01 seconds" is too small for humans to perceive. Over larger time experiences, the occurrences of "c=1,e=0" (and "c=2,e=1" and so on) will be offset by lots of occurrences of "c=0,e=1" (which will probably go unnoticed, by the way) which will tend to cancel aggregations of overall error.  

Cary Millsap
Hotsos Enterprises, Ltd.
http://www.hotsos.com

Upcoming events:

- Hotsos  <http://www.hotsos.com/training/clinic> Clinic, Jul 9-11 New York City
- Hotsos Clinic <http://www.hotsos.com/training/clinic> , Jul 23-25 Chicago
- 2003 Hotsos Symposium <http://www.hotsos.com>  on OracleŽ System Performance, Feb 9-12 Dallas

-----Original Message-----
Tony
Sent: Monday, June 17, 2002 11:43 AM
To: Multiple recipients of list ORACLE-L event trace file output?  

The lines below show cpu times that are > elapsed.

<snip>

PARSE #1:c=1,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=3624295929
<more snipping>

EXEC #3:c=1,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=3624300816
<more snipping>

I've consumed Metalink and Hotsos documents on interpreting the raw trace file but I haven't found an explanation why this would be. My understanding is that the elapsed time would include the cpu value. Any insights would be greatly appreciated.

Tony Aponte

-- 
Please see the official ORACLE-L FAQ: http://www.orafaq.com
-- 
Author: Aponte, Tony
  INET: AponteT_at_hsn.net

Fat City Network Services    -- (858) 538-5051  FAX: (858) 538-5051
San Diego, California        -- Public Internet access / Mailing Lists
--------------------------------------------------------------------
To REMOVE yourself from this mailing list, send an E-Mail message
to: ListGuru_at_fatcity.com (note EXACT spelling of 'ListGuru') and in
the message BODY, include a line containing: UNSUB ORACLE-L
(or the name of mailing list you want to be removed from).  You may
also send the HELP command for other information (like subscribing).