| 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: tim column in trace output
Hi
We could always use the old programmer trick.
nm oracle | grep time "This will give os all external function with a
name like time"
after some "man" / "google" work gethrtime() look like interesting.
Assuming that gethrtime()
is the correct function it will be random depending on the hardware
platform / OS implementation
if it it possible to map the tim= value
NAME gethrtime, gethrvtime - get high resolution time
SYNOPSIS
#include <sys/time.h>
hrtime_t gethrtime(void);
hrtime_t gethrvtime(void);
DESCRIPTION
The gethrtime() function returns the current high-resolution
real time. Time is expressed as nanoseconds since some
arbitrary time in the past; it is not correlated in any way
to the time of day, and thus is not subject to resetting or
drifting by way of adjtime(2) <http://mirrors.ccs.neu.edu/cgi-bin/unixhelp/man-cgi?adjtime+2> or settimeofday(3C) <http://mirrors.ccs.neu.edu/cgi-bin/unixhelp/man-cgi?settimeofday+3>. The hi-
res timer is ideally suited to performance measurement
tasks, where cheap, accurate interval timing is required.
The gethrvtime() function returns the current high-
resolution LWP virtual time, expressed as total nanoseconds
of execution time. This function requires that micro state
accounting be enabled with the ptime utility (see proc(1) <http://mirrors.ccs.neu.edu/cgi-bin/unixhelp/man-cgi?proc+1>).
The gethrtime() and gethrvtime() functions both return an
hrtime_t, which is a 64-bit (long long) signed integer.
EXAMPLE
The following code fragment measures the average cost of
getpid(2) <http://mirrors.ccs.neu.edu/cgi-bin/unixhelp/man-cgi?getpid+2>:
hrtime_t start, end;
int i, iters = 100;
start = gethrtime();
for (i = 0; i < iters; i++)
getpid();
end = gethrtime();
printf("Avg getpid() time = %lld nsec\n", (end - start) / iters);
ATTRIBUTES
See attributes(5) <http://mirrors.ccs.neu.edu/cgi-bin/unixhelp/man-cgi?attributes+5> for descriptions of the following attri-
butes:
__________________________________
| ATTRIBUTE TYPE| ATTRIBUTE VALUE|
|_______________|__________________|_
| MT-Level | MT-Safe |
|_______________|_________________|
C Library Functions gethrtime(3C)
SEE ALSO
proc(1) <http://mirrors.ccs.neu.edu/cgi-bin/unixhelp/man-cgi?proc+1>, adjtime(2) <http://mirrors.ccs.neu.edu/cgi-bin/unixhelp/man-cgi?adjtime+2>, gettimeofday(3C) <http://mirrors.ccs.neu.edu/cgi-bin/unixhelp/man-cgi?gettimeofday+3>, settimeofday(3C) <http://mirrors.ccs.neu.edu/cgi-bin/unixhelp/man-cgi?settimeofday+3>, attributes(5) <http://mirrors.ccs.neu.edu/cgi-bin/unixhelp/man-cgi?attributes+5>
NOTES
Although the units of hi-res time are always the same
(nanoseconds), the actual resolution is hardware dependent.
Hi-res time is guaranteed to be monotonic (it won't go back-
ward, it won't periodically wrap) and linear (it won't occa-
sionally speed up or slow down for adjustment, like the time
of day can), but not necessarily unique: two sufficiently
proximate calls may return the same value.
SunOS 5.6 Last change: 10 Apr 1997 1
nm oracle | grep time
0a1c8020 T CD_time
0a109cf0 T LdiDateIntertimeAdd
0a10c7c0 T LdiDateIntertimeSubtract
0a055a10 T Osecs2time
0a0558f0 T Otime2secs
09f5d570 T T_time
U asctime@@GLIBC_2.0
5001a800 A atbdatetime_
U ctime@@GLIBC_2.0
U difftime@@GLIBC_2.0
0a130240 T gethrtime
U gettimeofday@@GLIBC_2.0
U gmtime@@GLIBC_2.0
U gmtime_r@@GLIBC_2.0
0939dcf0 T hokpgt_get_timestamp 0939d770 T hokpst_set_timestamp 0937b240 T holebl_bind_timestamp_ltz 0937b3a0 T holebnl_bind_name_timestamp_ltz0937ad00 T holebnt_bind_name_timestamp
0937e900 T holedbl_define_bind_variable_timestamp_ltz 0937e200 T holedbt_define_bind_variable_timestamp 0937e580 T holedbz_define_bind_variable_timestamp_tz0937ccf0 T holedl_define_variable_timestamp_ltz
0937cdc0 T holednl_define_variable_name_timestamp_ltz 0937c940 T holednt_define_variable_name_timestamp 0937cb80 T holednz_define_variable_name_timestamp_tz0937c870 T holedt_define_variable_timestamp 0937cab0 T holedz_define_variable_timestamp_tz
09381420 T holegvl_get_value_timestamp_ltz 093811a0 T holegvt_get_value_timestamp 093812e0 T holegvz_get_value_timestamp_tz 0937ea70 T holeldbn_timestamp_ltz_define_bind_variable_name0937e370 T holetdbn_timestamp_define_bind_variable_name 0937e6f0 T holezdbn_timestamp_tz_define_bind_variable_name 094000d0 T kdtimestamp
U localtime@@GLIBC_2.0
U localtime_r@@GLIBC_2.0
U mktime@@GLIBC_2.0
09de86c0 T pihtgtxto_get_transfer_timeout 09de88e0 T pihtqtxto_req_set_transfer_timeout 09de86a0 T pihtstxto_set_transfer_timeout09b60400 T pisodatetime
U pthread_cond_timedwait@@GLIBC_2.0
083c6220 T qcpi_datetime_literal
083e7b20 T qctdatetimeconv
0a01d6c0 T secs2time
U setitimer@@GLIBC_2.0
093d7b50 T shocodts_os_date_time_to_julian
0a0c8660 T sltspctimewait
0a02e8b0 T sntzgetcurtime
09f877c0 T snzdgmt_time
09ec8cd0 T snzjsgmt_time
U strftime@@GLIBC_2.0
0a01d5a0 T time2secs
U time@@GLIBC_2.0
U timezone@@GLIBC_2.0
Cary Millsap wrote:
>Djordje,
>
>Thanks for the information. I'll have to correct my statements about the
>Oracle9i Epoch. If the values you listed below were microsecond times
>that used 1/1/70 as the Epoch, then these numbers would represent times
>in February 1970:
>
>Your data:
>21/01/2003 22:46:50 4655566135078
>22/01/2003 07:11:46 4685152574608
>22/01/2003 11:24:55 4699984992031
>
>These tim values, if interpreted as Epoch=1/1/70 microsec times:
>$ perl tim.pl 4655566135078
>15:12:46.135078 Monday 23 February 1970
>$ perl tim.pl 4685152574608
>23:25:52.574608 Monday 23 February 1970
>$ perl tim.pl 4699984992031
>03:33:04.992031 Tuesday 24 February 1970
>
>Judging from the trace file you sent in your response to Mario, your 9i
>tim numbers are definitely microsecond values.
>
>I hate that my "tim Epoch is the Unix Epoch" theory is broken, at least
>for Solaris. However, I'll stand by my earlier statement that it's only
>a small disappointment, because no matter what the Epoch is, you can
>track tim values to the wall clock. Any time you want to want to
>construct a drift correction data point, you can emit the "***
><timestamp>" line to your trace data by calling DBMS_SYSTEM.KSDDDT.
>(Thanks, Julian Dyke, for that information.)
>
>
>Cary Millsap
>Hotsos Enterprises, Ltd.
>http://www.hotsos.com
>
>Upcoming events:
>- 2003 Hotsos Symposium, Feb 9-12 Dallas
>- RMOUG Training Days 2003, Mar 5-6 Denver
>- Hotsos Clinic 101, Mar 26-28 London
>
>
>-----Original Message-----
>Jankovic
>Sent: Sunday, January 26, 2003 10:19 PM
>To: Multiple recipients of list ORACLE-L
>
>Thanks Cary,
>
>At least on the database ver/platform I tried it (Oracle 9.2.0.1.0 on
>Sun
>Solaris 2.6) these do not appear to be milliseconds with unix Epoch.
>
>I ran "select sysdate from dual" in the traced sessions and compared the
>run-time with the tim column (so there could be around one second
>accuracy).
>The three of the results were:
>
>21/01/2003 22:46:50 4655566135078
>22/01/2003 07:11:46 4685152574608
>22/01/2003 11:24:55 4699984992031
>
>I've put them in a table and here is the reference time when tim is
>divided
>by 976562.5:
>
>select stm_date, stm_date-stm_tim/976562.5/86400
> 2 from ana_trace_tm
>
>STM_DATE STM_DATE-STM_TIM/97
>------------------- -------------------
>21/01/2003 22:46:50 27/11/2002 18:31:50
>22/01/2003 07:11:46 27/11/2002 18:31:50
>22/01/2003 11:24:55 27/11/2002 18:31:50
>
>BTW the factor I came up with was around 976,560 but as 976,562.5 is
>1,000,000,000/1024 I thought this could be the one that is in fact used
>by
>oracle.
>
>I tried today again and the factor drifted a bit to 976460, so I am not
>quite sure how credible it is, although in a reasonable trace period
>drifting is negligible. Your suggestion for synching wall clock and tim
>(item "4") is the one that we will probably use. The reason why I
>though
>having a wall clock of when the statement completed (as you nicely
>pointed
>out) could be of some help, is in, for example, comparing response times
>for
>the same statement during different times of days (different system
>load,
>etc.).
>
>Thanks for all the other comments.
>
>Djordje
>
>----- Original Message -----
>To: "Multiple recipients of list ORACLE-L" <ORACLE-L_at_fatcity.com>
>Sent: Friday, January 24, 2003 10:29 AM
>
>
>
>
>>Djordje,
>>
>>1. You're right; in Oracle8, tim is measured in centiseconds (0.01s).
>>
>>2. The value is the same as that found in v$timer.hsecs.
>>
>>3. We're not sure whether the Epoch for this clock is even meaningful
>>
>>
>or
>
>
>>not (I don't think we've been able to prove that the value resets when
>>you do an instance restart. Perhaps the value is a modulus of a
>>gettimeofday() value.)
>>
>>4. Item #3 has never really bothered us, because all we generally care
>>about is *relative* tim values, not absolute ones. You can establish a
>>mapping of tim values to wall clock values by comparing the timestamp
>>
>>
>in
>
>
>>a '***' line to the nearest tim value to it.
>>
>>5. Oracle9i makes life a little more fun, because tim values become
>>microsecond (0.000001s) values, and they appear to be unadulterated
>>gettimeofday() values, with an Epoch of 00:00:00 UTC, 1 January 1970
>>
>>
>(we
>
>
>>*think* this is true on all platforms). Hence, it becomes easy to
>>convert from tim values to wall clock values and back with a simple
>>
>>
>Perl
>
>
>>script that uses str2time and time2str function calls.
>>
>>6. Finally, a minor detail correction: the tim of a given line in the
>>trace file tells you the time at which the given cursor action
>>*completed*. You certainly aren't incorrect by saying it's the time
>>
>>
>that
>
>
>>something "ran," but saying "completed" is a little more precise.
>>
>>
>>Cary Millsap
>>Hotsos Enterprises, Ltd.
>>http://www.hotsos.com
>>
>>Upcoming events:
>>- 2003 Hotsos Symposium, Feb 9-12 Dallas
>>- RMOUG Training Days 2003, Mar 5-6 Denver
>>- Hotsos Clinic 101, Mar 26-28 London
>>
>>
>>-----Original Message-----
>>Jankovic
>>Sent: Friday, January 24, 2003 6:55 AM
>>To: Multiple recipients of list ORACLE-L
>>
>>Anybody knows what is the reference point for the timing used in the
>>"tim"
>>column in the trace output, like in:
>>
>>PARSE #3:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=832261739
>>EXEC #3:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=832261739
>>
>>Apparently the scale is 100 per second for 8i and 976,562.5
>>(1,000,000,000/1024) for 9, but I am not quite clear what could be the
>>reference time (the time when counting of tim starts). In different
>>databases I tried it, it is usually few months to a year back.
>>
>>BTW, this column can be used if one needs to find out the exact time
>>when a
>>query from the trace was run.
>>
>>Thanks.
>>
>>Djordje
>>
>>--
>>Please see the official ORACLE-L FAQ: http://www.orafaq.net
>>--
>>Author: Djordje Jankovic
>> INET: djordjej_at_rogers.com
>>
>>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: 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).
>>
>>--
>>Please see the official ORACLE-L FAQ: http://www.orafaq.net
>>--
>>Author: Cary Millsap
>> INET: cary.millsap_at_hotsos.com
>>
>>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: 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).
>>
>>
>>
>
>
>
>
-- Peter Gram, Miracle A/S Phone : +45 2527 7107, Fax : +45 4466 8856 mailto:peter.gram@MiracleAS.dk - http://MiracleAS.dkReceived on Tue Jan 28 2003 - 02:03:52 CSTContent-Type: text/plain; name="ReadMe.txt"; charset="us-ascii" Content-Transfer-Encoding: 7bit The previous attachment was filtered out by the ListGuru mailing software at fatcity.com because binary attachments are not appropriate for mailing lists. If you want a copy of the attachment which was removed, contact the sender directly and ask for it to be sent to you by private E-mail. This warning is inserted into all messages containing binary attachments which have been removed by ListGuru. If you have questions about this message, contact Postmaster_at_fatcity.com for clarification. --------------ms030204020403070907080806-- -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Peter Gram INET: peter.gram_at_miracleas.dk 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: 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).
- application/x-pkcs7-signature attachment: smime.p7s
 |
 |