Oracle-L: RE: tim column in trace output

From: Cary Millsap <cary.millsap_at_hotsos.com>
Date: Mon, 27 Jan 2003 07:59:56 -0800
Message-ID: <F001.0053B20A.20030127075956@fatcity.com>

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

> ---------------------------------------------------------------------

-- 
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).

Received on Mon Jan 27 2003 - 09:59:56 CST