Oracle FAQ Your Portal to the Oracle Knowledge Grid
HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US
 

Home -> Community -> Mailing Lists -> Oracle-L -> RE: Have I misinterpreted the e= and c= relationship in 10046 event trace file output?

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

From: Cary Millsap <cary.millsap_at_hotsos.com>
Date: Mon, 17 Jun 2002 11:08:32 -0800
Message-ID: <F001.0047F74B.20020617110832@fatcity.com>


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 Clinic <http://www.hotsos.com/training/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 OracleR System Performance, Feb 9-12 Dallas

-----Original Message-----
Tony
Sent: Monday, June 17, 2002 11:43 AM
To: Multiple recipients of list ORACLE-L 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: Cary Millsap
  INET: cary.millsap_at_hotsos.com

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).
Received on Mon Jun 17 2002 - 14:08:32 CDT

Original text of this message

HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US