RE: raw traces - EXEC: c=10,000 e=40
Cary, thanks a lot for the explanation (and the other one [and especially the other one :-) ]). Much appreciated. --- Cary Millsap [EMAIL PROTECTED] wrote: You're on the right trail by experimenting with it. I'm surprised that the number of gettimeofday() calls is so small. The times() call is the SVR4 analog of the BSD getrusage() call. I guess I shouldn't be surprised to see both times() and getrusage() being used. Cary Millsap Hotsos Enterprises, Ltd. http://www.hotsos.com Upcoming events: - Performance Diagnosis 101: 12/16 Detroit, 1/27 Atlanta - SQL Optimization 101: 12/8 Dallas, 2/16 Dallas - Hotsos Symposium 2004: March 7-10 Dallas - Visit www.hotsos.com for schedule details... === message truncated === __ Post your free ad now! http://personals.yahoo.ca -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Boris Dali INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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).
FW: raw traces - EXEC: c=10,000 e=40
Wolfgang, The OS has always provided microsecond data to the Oracle kernel (see the 'man gettimeofday' and 'man getrusage'). It's only in release 9 that the Oracle kernel stopped truncating the data at the centisecond digit (by doing an integer division of 1). Oracle gets elapsed times by comparing pairs of gettimeofday() calls (truss to find out for yourself). The e=40us is actually accurate to within +/-1us (not counting measurement intrusion effect). The c value is potentially way off, as I explained in the other note. Cary Millsap Hotsos Enterprises, Ltd. http://www.hotsos.com Upcoming events: - Performance Diagnosis 101: 12/16 Detroit, 1/27 Atlanta - SQL Optimization 101: 12/8 Dallas, 2/16 Dallas - Hotsos Symposium 2004: March 7-10 Dallas - Visit www.hotsos.com for schedule details... -Original Message- Wolfgang Breitling Sent: Tuesday, December 02, 2003 3:54 PM To: Multiple recipients of list ORACLE-L In Oracle 9, Oracle tries to measure times in microseconds (as opposed to centiseconds pre-9). However, many Systems only slice time far coarser than that so Oracle has to fake it to some degree and that faking may be different between cpu time and elapsed time. Take your cpu times for example. They are all 1 microseconds which is exactly 1/100 = 0.01 = 1 centiseconds. That's a bit too much of a coincidence for me. Who knows where Oracle get the elapsed times from. I wouldn't put too much faith in the accuracy of an purported elapsed time of 40 microseconds. Unless we are getting at least into the milliseconds range I would regard all elapsed times as rounding errors. At 02:09 PM 12/2/2003, you wrote: Hi! I haven't read Cary's book yet (although it's already waiting on my bookshelf), but I think CPU time c is measured in timeslice steps (100ms) and elapsed time e is taken from system timer or smth like that. Others will know better :) Tanel. - Original Message - To: Multiple recipients of list ORACLE-L [EMAIL PROTECTED] Sent: Tuesday, December 02, 2003 10:49 PM Reading Cary's book I understand that c and e are measured via different system calls (haven't truss'ed [well tusc'ed] them yet - I am on HP-UX 11.11), but would anybody know what the reasonable upper limit of c-e might be? I am looking at the trace file where c is more than two orders of magnitude greater than e, which make me wonder if I a have some anomaly on my system Some examples: EXEC #98:c=1,e=433,p=0,cr=2,cu=2,mis=0,r=1,dep=1,og=4,tim=1777312113968 EXEC #110:c=1,e=390,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=4,tim=1777312181650 PARSE #103:c=1,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1777314524922 Oracle 9.2.0.4.0 on HP-UX 11.11 Thanks, Boris Dali. __ Post your free ad now! http://personals.yahoo.ca -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Boris Dali INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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). -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Tanel Poder INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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). Wolfgang Breitling Oracle7, 8, 8i, 9i OCP DBA Centrex Consulting Corporation http://www.centrexcc.com -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Wolfgang Breitling INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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). --
Re: FW: raw traces - EXEC: c=10,000 e=40
Thanks for the clarification. At 10:29 AM 12/3/2003, you wrote: Wolfgang, The OS has always provided microsecond data to the Oracle kernel (see the 'man gettimeofday' and 'man getrusage'). It's only in release 9 that the Oracle kernel stopped truncating the data at the centisecond digit (by doing an integer division of 1). Oracle gets elapsed times by comparing pairs of gettimeofday() calls (truss to find out for yourself). The e=40us is actually accurate to within +/-1us (not counting measurement intrusion effect). The c value is potentially way off, as I explained in the other note. Cary Millsap Hotsos Enterprises, Ltd. http://www.hotsos.com Wolfgang Breitling Oracle7, 8, 8i, 9i OCP DBA Centrex Consulting Corporation http://www.centrexcc.com -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Wolfgang Breitling INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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).
RE: raw traces - EXEC: c=10,000 e=40
Is this true? strace-ing on linux shows gettimeofday calls (for e) and getrusage (for c) - just like Cary describes. On HP however tusc-ing a simple select * from dual issued from sqlplus I see: calls sys call - 1 gettimeofday() 1 getrusage() 15times() Which sys call is used for what? Guess I can turn timed_statistics off and see how it affects the (amount of) sys calls issued Thanks, Boris Dali. --- Niall Litchfield [EMAIL PROTECTED] wrote: me reads Jonathan's description and blushes/me So it'll be a *feature* and not a bug then. IIRC e comes from POSIX gettimeofday calls on all platforms except Windows -- where it looks like GetTickCount. If this is true then the accuracy of e will be limited by the accuracy of gettimeofday. Niall -Original Message- From: [EMAIL PROTECTED] [mailto:[EMAIL PROTECTED] On Behalf Of Niall Litchfield Sent: 02 December 2003 22:24 To: Multiple recipients of list ORACLE-L Subject: RE: raw traces - EXEC: c=10,000 e=40 I'd be highly, highly suspicious of the cpu time c. 1. You should be able to verify (roughly the elapsed time) of the statement, if by no other means than running in sqlplus with timing on. 2. 3 statements with *exactly* the same cpu time - all in very very round numbers. Seems unlikely to me. Might be an hp-ux bug but as I don't have HP-UX to play with that is speculation of the first order. Niall -Original Message- From: [EMAIL PROTECTED] [mailto:[EMAIL PROTECTED] On Behalf Of Boris Dali Sent: 02 December 2003 20:49 To: Multiple recipients of list ORACLE-L Subject: raw traces - EXEC: c=10,000 e=40 Reading Cary's book I understand that c and e are measured via different system calls (haven't truss'ed [well tusc'ed] them yet - I am on HP-UX 11.11), but would anybody know what the reasonable upper limit of c-e might be? I am looking at the trace file where c is more than two orders of magnitude greater than e, which make me wonder if I a have some anomaly on my system Some examples: EXEC #98:c=1,e=433,p=0,cr=2,cu=2,mis=0,r=1,dep=1,og=4,tim=1777312113968 EXEC #110:c=1,e=390,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=4,tim=1777 312181650 PARSE #103:c=1,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1777314524922 Oracle 9.2.0.4.0 on HP-UX 11.11 Thanks, Boris Dali. __ Post your free ad now! http://personals.yahoo.ca -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Boris Dali INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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). -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Niall Litchfield INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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). -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Niall Litchfield INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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). __ Post your free ad now! http://personals.yahoo.ca -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Boris Dali INET: [EMAIL PROTECTED] Fat City Network Services-- 858
RE: raw traces - EXEC: c=10,000 e=40
The gettimeofday() function obtains the current time, expressed as
seconds and microseconds since 00:00 Coordinated Universal Time
(UTC),
January 1, 1970, and stores it in the timeval structure pointed
to by
tp. The resolution of the system clock is unspecified.
The getrusage() function provides measures of the resources used by
the current process or its terminated and waited-for child
processes.
If the value of the who argument is RUSAGE_SELF, information is
returned about resources used by the current process. If the value
of
the who argument is RUSAGE_CHILDREN, information is returned about
resources used by the terminated and waited-for children of the
current process. If the child is never waited for (for instance,
if
the parent has SA_NOCLDWAIT set or sets SIGCHLD to SIG_IGN), the
resource information for the child process is discarded and not
included in the resource information provided by getrusage(). The
r_usage argument is a pointer to an object of type struct rusage
in
which the returned information is stored
times() fills the structure pointed to by buffer with time-accounting
information. The structure defined in sys/times.h is as
follows:
struct tms {
clock_t tms_utime; /* user time */
clock_t tms_stime; /* system time */
clock_t tms_cutime; /* user time, children */
clock_t tms_cstime; /* system time, children */
};
This information comes from the calling process and each of its
terminated child processes for which it has executed a wait(),
These are from HPUX 11.11. In HPUX and all other unix execute man your
command or system call to get more information.
Allan
-Original Message-
Boris Dali
Sent: Wednesday, December 03, 2003 12:29 PM
To: Multiple recipients of list ORACLE-L
Is this true? strace-ing on linux shows gettimeofday
calls (for e) and getrusage (for c) - just like Cary
describes. On HP however tusc-ing a simple select *
from dual issued from sqlplus I see:
calls sys call
-
1 gettimeofday()
1 getrusage()
15times()
Which sys call is used for what?
Guess I can turn timed_statistics off and see how it
affects the (amount of) sys calls issued
Thanks,
Boris Dali.
--- Niall Litchfield
[EMAIL PROTECTED] wrote: me reads Jonathan's
description and blushes/me
So it'll be a *feature* and not a bug then. IIRC e
comes from POSIX
gettimeofday calls on all platforms except Windows
-- where it looks
like GetTickCount. If this is true then the accuracy
of e will be
limited by the accuracy of gettimeofday.
Niall
-Original Message-
From: [EMAIL PROTECTED]
[mailto:[EMAIL PROTECTED] On
Behalf Of Niall Litchfield
Sent: 02 December 2003 22:24
To: Multiple recipients of list ORACLE-L
Subject: RE: raw traces - EXEC: c=10,000 e=40
I'd be highly, highly suspicious of the cpu time
c.
1. You should be able to verify (roughly the
elapsed time) of
the statement, if by no other means than running
in sqlplus
with timing on.
2. 3 statements with *exactly* the same cpu time -
all in
very very round numbers. Seems unlikely to me.
Might be an hp-ux bug but as I don't have HP-UX to
play with
that is speculation of the first order.
Niall
-Original Message-
From: [EMAIL PROTECTED]
[mailto:[EMAIL PROTECTED] On
Behalf Of Boris Dali
Sent: 02 December 2003 20:49
To: Multiple recipients of list ORACLE-L
Subject: raw traces - EXEC: c=10,000 e=40
Reading Cary's book I understand that c and e
are
measured via different system calls (haven't
truss'ed
[well tusc'ed] them yet - I am on HP-UX 11.11),
but
would anybody know what the reasonable upper
limit of
c-e might be?
I am looking at the trace file where c is more
than
two orders of magnitude greater than e, which
make me
wonder if I a have some anomaly on my system
Some examples:
EXEC
#98:c=1,e=433,p=0,cr=2,cu=2,mis=0,r=1,dep=1,og=4,tim=1777312113968
EXEC
#110:c=1,e=390,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=4,tim=1777
312181650
PARSE
#103:c=1,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1777314524922
Oracle 9.2.0.4.0 on HP-UX 11.11
Thanks,
Boris Dali.
__
Post your free ad now! http://personals.yahoo.ca
--
Please see the official ORACLE-L FAQ:
http://www.orafaq.net
--
Author: Boris Dali
INET: [EMAIL PROTECTED]
Fat City Network Services-- 858-538-5051
http://www.fatcity.com
San Diego, California-- Mailing list and
web
hosting services
-
To REMOVE yourself from this mailing list, send
an E
RE: raw traces - EXEC: c=10,000 e=40
You're on the right trail by experimenting with it. I'm surprised that the number of gettimeofday() calls is so small. The times() call is the SVR4 analog of the BSD getrusage() call. I guess I shouldn't be surprised to see both times() and getrusage() being used. Cary Millsap Hotsos Enterprises, Ltd. http://www.hotsos.com Upcoming events: - Performance Diagnosis 101: 12/16 Detroit, 1/27 Atlanta - SQL Optimization 101: 12/8 Dallas, 2/16 Dallas - Hotsos Symposium 2004: March 7-10 Dallas - Visit www.hotsos.com for schedule details... -Original Message- Boris Dali Sent: Wednesday, December 03, 2003 12:29 PM To: Multiple recipients of list ORACLE-L Is this true? strace-ing on linux shows gettimeofday calls (for e) and getrusage (for c) - just like Cary describes. On HP however tusc-ing a simple select * from dual issued from sqlplus I see: calls sys call - 1 gettimeofday() 1 getrusage() 15times() Which sys call is used for what? Guess I can turn timed_statistics off and see how it affects the (amount of) sys calls issued Thanks, Boris Dali. --- Niall Litchfield [EMAIL PROTECTED] wrote: me reads Jonathan's description and blushes/me So it'll be a *feature* and not a bug then. IIRC e comes from POSIX gettimeofday calls on all platforms except Windows -- where it looks like GetTickCount. If this is true then the accuracy of e will be limited by the accuracy of gettimeofday. Niall -Original Message- From: [EMAIL PROTECTED] [mailto:[EMAIL PROTECTED] On Behalf Of Niall Litchfield Sent: 02 December 2003 22:24 To: Multiple recipients of list ORACLE-L Subject: RE: raw traces - EXEC: c=10,000 e=40 I'd be highly, highly suspicious of the cpu time c. 1. You should be able to verify (roughly the elapsed time) of the statement, if by no other means than running in sqlplus with timing on. 2. 3 statements with *exactly* the same cpu time - all in very very round numbers. Seems unlikely to me. Might be an hp-ux bug but as I don't have HP-UX to play with that is speculation of the first order. Niall -Original Message- From: [EMAIL PROTECTED] [mailto:[EMAIL PROTECTED] On Behalf Of Boris Dali Sent: 02 December 2003 20:49 To: Multiple recipients of list ORACLE-L Subject: raw traces - EXEC: c=10,000 e=40 Reading Cary's book I understand that c and e are measured via different system calls (haven't truss'ed [well tusc'ed] them yet - I am on HP-UX 11.11), but would anybody know what the reasonable upper limit of c-e might be? I am looking at the trace file where c is more than two orders of magnitude greater than e, which make me wonder if I a have some anomaly on my system Some examples: EXEC #98:c=1,e=433,p=0,cr=2,cu=2,mis=0,r=1,dep=1,og=4,tim=1777312113968 EXEC #110:c=1,e=390,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=4,tim=1777 312181650 PARSE #103:c=1,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1777314524922 Oracle 9.2.0.4.0 on HP-UX 11.11 Thanks, Boris Dali. __ Post your free ad now! http://personals.yahoo.ca -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Boris Dali INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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). -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Niall Litchfield INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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). -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Niall Litchfield INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services
raw traces - EXEC: c=10,000 e=40
Reading Cary's book I understand that c and e are measured via different system calls (haven't truss'ed [well tusc'ed] them yet - I am on HP-UX 11.11), but would anybody know what the reasonable upper limit of c-e might be? I am looking at the trace file where c is more than two orders of magnitude greater than e, which make me wonder if I a have some anomaly on my system Some examples: EXEC #98:c=1,e=433,p=0,cr=2,cu=2,mis=0,r=1,dep=1,og=4,tim=1777312113968 EXEC #110:c=1,e=390,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=4,tim=1777312181650 PARSE #103:c=1,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1777314524922 Oracle 9.2.0.4.0 on HP-UX 11.11 Thanks, Boris Dali. __ Post your free ad now! http://personals.yahoo.ca -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Boris Dali INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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).
Re: raw traces - EXEC: c=10,000 e=40
Hi! I haven't read Cary's book yet (although it's already waiting on my bookshelf), but I think CPU time c is measured in timeslice steps (100ms) and elapsed time e is taken from system timer or smth like that. Others will know better :) Tanel. - Original Message - To: Multiple recipients of list ORACLE-L [EMAIL PROTECTED] Sent: Tuesday, December 02, 2003 10:49 PM Reading Cary's book I understand that c and e are measured via different system calls (haven't truss'ed [well tusc'ed] them yet - I am on HP-UX 11.11), but would anybody know what the reasonable upper limit of c-e might be? I am looking at the trace file where c is more than two orders of magnitude greater than e, which make me wonder if I a have some anomaly on my system Some examples: EXEC #98:c=1,e=433,p=0,cr=2,cu=2,mis=0,r=1,dep=1,og=4,tim=1777312113968 EXEC #110:c=1,e=390,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=4,tim=1777312181650 PARSE #103:c=1,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1777314524922 Oracle 9.2.0.4.0 on HP-UX 11.11 Thanks, Boris Dali. __ Post your free ad now! http://personals.yahoo.ca -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Boris Dali INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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). -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Tanel Poder INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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).
Re: raw traces - EXEC: c=10,000 e=40
In Oracle 9, Oracle tries to measure times in microseconds (as opposed to centiseconds pre-9). However, many Systems only slice time far coarser than that so Oracle has to fake it to some degree and that faking may be different between cpu time and elapsed time. Take your cpu times for example. They are all 1 microseconds which is exactly 1/100 = 0.01 = 1 centiseconds. That's a bit too much of a coincidence for me. Who knows where Oracle get the elapsed times from. I wouldn't put too much faith in the accuracy of an purported elapsed time of 40 microseconds. Unless we are getting at least into the milliseconds range I would regard all elapsed times as rounding errors. At 02:09 PM 12/2/2003, you wrote: Hi! I haven't read Cary's book yet (although it's already waiting on my bookshelf), but I think CPU time c is measured in timeslice steps (100ms) and elapsed time e is taken from system timer or smth like that. Others will know better :) Tanel. - Original Message - To: Multiple recipients of list ORACLE-L [EMAIL PROTECTED] Sent: Tuesday, December 02, 2003 10:49 PM Reading Cary's book I understand that c and e are measured via different system calls (haven't truss'ed [well tusc'ed] them yet - I am on HP-UX 11.11), but would anybody know what the reasonable upper limit of c-e might be? I am looking at the trace file where c is more than two orders of magnitude greater than e, which make me wonder if I a have some anomaly on my system Some examples: EXEC #98:c=1,e=433,p=0,cr=2,cu=2,mis=0,r=1,dep=1,og=4,tim=1777312113968 EXEC #110:c=1,e=390,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=4,tim=1777312181650 PARSE #103:c=1,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1777314524922 Oracle 9.2.0.4.0 on HP-UX 11.11 Thanks, Boris Dali. __ Post your free ad now! http://personals.yahoo.ca -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Boris Dali INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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). -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Tanel Poder INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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). Wolfgang Breitling Oracle7, 8, 8i, 9i OCP DBA Centrex Consulting Corporation http://www.centrexcc.com -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Wolfgang Breitling INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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).
Re: raw traces - EXEC: c=10,000 e=40
On your platform, c is measured in centiseconds (10,000 microseconds) whilst e has a notional accuracy to the microsecond. So the extremes are to be expected. Regards Jonathan Lewis http://www.jlcomp.demon.co.uk The educated person is not the person who can answer the questions, but the person who can question the answers -- T. Schick Jr One-day tutorials: http://www.jlcomp.demon.co.uk/tutorial.html Three-day seminar: see http://www.jlcomp.demon.co.uk/seminar.html UK___November The Co-operative Oracle Users' FAQ http://www.jlcomp.demon.co.uk/faq/ind_faq.html - Original Message - To: Multiple recipients of list ORACLE-L [EMAIL PROTECTED] Sent: Tuesday, December 02, 2003 8:49 PM Reading Cary's book I understand that c and e are measured via different system calls (haven't truss'ed [well tusc'ed] them yet - I am on HP-UX 11.11), but would anybody know what the reasonable upper limit of c-e might be? I am looking at the trace file where c is more than two orders of magnitude greater than e, which make me wonder if I a have some anomaly on my system Some examples: EXEC #98:c=1,e=433,p=0,cr=2,cu=2,mis=0,r=1,dep=1,og=4,tim=1777312113968 EXEC #110:c=1,e=390,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=4,tim=1777312181650 PARSE #103:c=1,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1777314524922 Oracle 9.2.0.4.0 on HP-UX 11.11 Thanks, Boris Dali. __ Post your free ad now! http://personals.yahoo.ca -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Boris Dali INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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). -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Jonathan Lewis INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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).
RE: raw traces - EXEC: c=10,000 e=40
I'd be highly, highly suspicious of the cpu time c. 1. You should be able to verify (roughly the elapsed time) of the statement, if by no other means than running in sqlplus with timing on. 2. 3 statements with *exactly* the same cpu time - all in very very round numbers. Seems unlikely to me. Might be an hp-ux bug but as I don't have HP-UX to play with that is speculation of the first order. Niall -Original Message- From: [EMAIL PROTECTED] [mailto:[EMAIL PROTECTED] On Behalf Of Boris Dali Sent: 02 December 2003 20:49 To: Multiple recipients of list ORACLE-L Subject: raw traces - EXEC: c=10,000 e=40 Reading Cary's book I understand that c and e are measured via different system calls (haven't truss'ed [well tusc'ed] them yet - I am on HP-UX 11.11), but would anybody know what the reasonable upper limit of c-e might be? I am looking at the trace file where c is more than two orders of magnitude greater than e, which make me wonder if I a have some anomaly on my system Some examples: EXEC #98:c=1,e=433,p=0,cr=2,cu=2,mis=0,r=1,dep=1,og=4,tim=1777312113968 EXEC #110:c=1,e=390,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=4,tim=1777 312181650 PARSE #103:c=1,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1777314524922 Oracle 9.2.0.4.0 on HP-UX 11.11 Thanks, Boris Dali. __ Post your free ad now! http://personals.yahoo.ca -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Boris Dali INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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). -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Niall Litchfield INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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).
RE: raw traces - EXEC: c=10,000 e=40
me reads Jonathan's description and blushes/me So it'll be a *feature* and not a bug then. IIRC e comes from POSIX gettimeofday calls on all platforms except Windows -- where it looks like GetTickCount. If this is true then the accuracy of e will be limited by the accuracy of gettimeofday. Niall -Original Message- From: [EMAIL PROTECTED] [mailto:[EMAIL PROTECTED] On Behalf Of Niall Litchfield Sent: 02 December 2003 22:24 To: Multiple recipients of list ORACLE-L Subject: RE: raw traces - EXEC: c=10,000 e=40 I'd be highly, highly suspicious of the cpu time c. 1. You should be able to verify (roughly the elapsed time) of the statement, if by no other means than running in sqlplus with timing on. 2. 3 statements with *exactly* the same cpu time - all in very very round numbers. Seems unlikely to me. Might be an hp-ux bug but as I don't have HP-UX to play with that is speculation of the first order. Niall -Original Message- From: [EMAIL PROTECTED] [mailto:[EMAIL PROTECTED] On Behalf Of Boris Dali Sent: 02 December 2003 20:49 To: Multiple recipients of list ORACLE-L Subject: raw traces - EXEC: c=10,000 e=40 Reading Cary's book I understand that c and e are measured via different system calls (haven't truss'ed [well tusc'ed] them yet - I am on HP-UX 11.11), but would anybody know what the reasonable upper limit of c-e might be? I am looking at the trace file where c is more than two orders of magnitude greater than e, which make me wonder if I a have some anomaly on my system Some examples: EXEC #98:c=1,e=433,p=0,cr=2,cu=2,mis=0,r=1,dep=1,og=4,tim=1777312113968 EXEC #110:c=1,e=390,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=4,tim=1777 312181650 PARSE #103:c=1,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1777314524922 Oracle 9.2.0.4.0 on HP-UX 11.11 Thanks, Boris Dali. __ Post your free ad now! http://personals.yahoo.ca -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Boris Dali INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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). -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Niall Litchfield INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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). -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Niall Litchfield INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (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).
RE: raw traces - EXEC: c=10,000 e=40
Boris, Your three cases are a simpler manifestation of the problem described in Figure 7-8 of Optimizing Oracle Performance (pp163-165). Each of the three db calls you show happened to be either in the 'kernel running' or 'user running' OS process state when a scheduler interrupt occurred. Each time this occurred, your OS allocated a full 1/100-second unit of CPU capacity consumption to the process. 1/100th of a second equals 10,000 microseconds, so this is why you see c=1. Yes, the true elapsed time of the call is a known upper bound on the true CPU consumption, but without microstate accounting (Sun Solaris), you can't know the true CPU consumption except to know that it was somewhere between 0 and the value of e. It's easy to become sad at this point. For example, Oracle CPU statistics are accurate only to the nearest 10,000 microseconds sounds really bad. Well, it's not true; it's much worse than that. Each c statistic can be off by *far* more than 10,000 microseconds! I'll show you why in a minute. But don't worry. There are lots of other db calls in your trace file that look like c=0,e=29862, which might have been more accurate had they said c=1 or maybe c=2. You can't correct for these, because you can't know how much correction is required. It's tempting to correct c=1,e=40 because you know the real c couldn't have exceeded 40, BUT DON'T. If you correct for neither problem, then statistics are on your side. Over the course of a many-line trace file, the total quantization error tends toward zero. In other words, if you sum your c values and sum your e values for a whole file, the total error is much smaller than it would appear by observing lots of scary c=1,e=40 cases. If you try to correct the overestimation problem, you just make things worse (because it's impossible to determine when you have a corresponding underestimation problem). To answer your question directly, I think the range of c-e for a single db call is -e c-e 10,000us. Here's my reasoning: c=1,e=x (where x is much smaller than 10,000) Stuff like this happens all the time (as you've observed). It happens when a scheduler interrupt occurs anytime during the x-us execution duration. Of course, the probability of this occurring is approximately x/10,000, so the smaller your value of x, the less likely you'll find this occurring. But even c=1,e=0 is possible. c=2,e=x (where x is much smaller than 10,000) I don't think this can happen as long as there's a single scheduler interrupt for all the CPUs of an SMP system. For two scheduler interrupts to take place during the elapsed duration of a db call, the db call duration would have to be at least e=1. In general (induction step here), I think it's impossible to register a c=N value unless e has a value of at least N-1. So I think the largest positive value c-e could take on is 10,000us. c=0,e=x (where x is arbitrarily large) This one can happen for all sorts of values of x, and I mean LARGE ones. Imagine a db call that runs for e=100,000,000 (commas for clarity; this is 100 seconds). It's entirely possible (though highly improbable) that the process happens never actually to be using a CPU during a scheduler interrupt. Therefore, I believe that c-e can be arbitrarily large in the negative direction. It is improbable in direct proportion to the size of e=x that c will be zero, but it's possible. Therefore, I think the bounds of the error c-e are probably -e c-e 10,000us. * * * But, again, don't worry. The likelihood of an overestimated c approximates the likelihood of an underestimated c. Over the course of a largish trace file, it is highly unlikely that the quantization error on the sum of your c statistics will propagate very far in either the overestimate or the underestimate direction. And practical experience bears this out. Our Hotsos Profiler uses this information to full advantage. Cary Millsap Hotsos Enterprises, Ltd. http://www.hotsos.com Upcoming events: - Performance Diagnosis 101: 12/16 Detroit, 1/27 Atlanta - SQL Optimization 101: 12/8 Dallas, 2/16 Dallas - Hotsos Symposium 2004: March 7-10 Dallas - Visit www.hotsos.com for schedule details... -Original Message- Boris Dali Sent: Tuesday, December 02, 2003 2:49 PM To: Multiple recipients of list ORACLE-L Reading Cary's book I understand that c and e are measured via different system calls (haven't truss'ed [well tusc'ed] them yet - I am on HP-UX 11.11), but would anybody know what the reasonable upper limit of c-e might be? I am looking at the trace file where c is more than two orders of magnitude greater than e, which make me wonder if I a have some anomaly on my system Some examples: EXEC #98:c=1,e=433,p=0,cr=2,cu=2,mis=0,r=1,dep=1,og=4,tim=1777312113968 EXEC #110:c=1,e=390,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=4,tim=1777312181650 PARSE #103:c=1,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1777314524922 Oracle 9.2.0.4.0 on HP-UX 11.11
