Thread: Event 10046 and timestamp


Permlink Replies: 7 - Pages: 1 - Last Post: Oct 4, 2008 12:36 AM Last Post By: user489622
Leo Anderson

Posts: 243
Registered: 08/29/07
Event 10046 and timestamp
Posted: Aug 18, 2008 11:30 PM
Click to report abuse...   Click to reply to this thread Reply
Hi,

When setting event 10046 for tuning purpose, I'd like to get the timestamp to compare with other logs (application, OS, ...)

Is it possible ?

How to convert "tim=8317892534" in readable date/time ?

Thanks,

Leo.
riedelme

Posts: 1,535
Registered: 04/03/02
Re: Event 10046 and timestamp
Posted: Aug 19, 2008 1:11 PM   in response to: Leo Anderson in response to: Leo Anderson
Click to report abuse...   Click to reply to this thread Reply
You can't easily convert the tim value because it does not reference a real time. You could try to simulate this by corrdinating it with a starting time and adding ahead but I'm doubtful about how accurate that would be
Charles Hooper

Posts: 754
Registered: 01/27/08
Re: Event 10046 and timestamp
Posted: Aug 19, 2008 1:30 PM   in response to: Leo Anderson in response to: Leo Anderson
Click to report abuse...   Click to reply to this thread Reply
Leo,

The answer will depend on the operating system and Oracle version. Prior to Oracle 9i, it is possible to divide the tim= values by 100 to convert the number to seconds. Starting with Oracle 9i, it is possible to divide the tim= values by 1000000 to convert the number to seconds. If I remember correctly, on Unix/Linux, the tim= value may be used to determine the number of seconds elapsed since the Unix epoch, which is midnight Jan 1, 1970. On Windows, it is not quite as clear. Even on 64 bit Oracle 10g R2 running on Windows, the value of tim= may wrap around during the capture of the trace, as if it were a 32 bit unsigned integer (2^32 = 4294967296 = wrap roughly every 4294.967296 seconds).

The start of the trace file should contain the trace start time:
Ex: Tue Aug 19 08:16:14 2008
Periodically, you should find Oracle emitting the current date and time in the trace file:
Ex: *** 2008-08-19 08:16:25.513

Hopefully, the above will help.

Charles Hooper
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc.
Leo Anderson

Posts: 243
Registered: 08/29/07
Re: Event 10046 and timestamp
Posted: Aug 19, 2008 11:41 PM   in response to: Charles Hooper in response to: Charles Hooper
Click to report abuse...   Click to reply to this thread Reply
Hi,

were did you get those informations about the unix/windows differences, the factor used for converting ?

Are the results could be considered as definitive ?

Thanks,

Leo.
P. Forstmann

Posts: 2,415
Registered: 01/26/07
Re: Event 10046 and timestamp
Posted: Aug 20, 2008 12:12 AM   in response to: Leo Anderson in response to: Leo Anderson
Click to report abuse...   Click to reply to this thread Reply
About Oracle 9 you can find some info in Optimizing Oracle Performance book.

Metalink note Interpreting Raw SQL_TRACE and DBMS_SUPPORT.START_TRACE output gives some limited details.
Leo Anderson

Posts: 243
Registered: 08/29/07
Re: Event 10046 and timestamp
Posted: Aug 20, 2008 2:21 AM   in response to: P. Forstmann in response to: P. Forstmann
Click to report abuse...   Click to reply to this thread Reply
"limited details".... that's the exact words ! :p
Charles Hooper

Posts: 754
Registered: 01/27/08
Re: Event 10046 and timestamp
Posted: Aug 20, 2008 4:19 AM   in response to: Leo Anderson in response to: Leo Anderson
Click to report abuse...   Click to reply to this thread Reply
were did you get those informations about the
unix/windows differences, the factor used for
converting ?

Are the results could be considered as definitive ?


I have worked with 10046 trace files since reading Cary Millsap's "Optimizing Oracle Performance" book shortly after the book was released - it is quite amazing the amount of detail that may be extracted from such files. If you have access to that book, take a look at the middle of page 79 for an explanation of the tim= meaning. It is a bit frustrating attempting to time sequence trace files generated on Windows platforms, especially when the tim values wrap around, where a tim value further down the trace file is smaller than the current line.

There are other sources for various bits and pieces of information that may be used to help decode 10046 trace files, but sometimes it is hard to determine which sources are correct, so it helps to be willing to experiment. Message threads that may be of interest:
http://www.freelists.org/archives/oracle-l/03-2004/msg03083.html
http://www.freelists.org/archives/oracle-l/03-2007/msg01119.html
http://www.jlcomp.demon.co.uk/faq/time_unit.html

The second and third of the above links indicates that powers of 2 (rather than powers of 10) may also be a factor on some platforms.

Samples that show the differences in tim= values between Linux and Windows:
Linux box running 9.2.0.4:
*** 2007-08-31 11:11:04.729
PARSING IN CURSOR #34 len=42 dep=1 uid=0 oct=3 lid=0 tim=1160715883626949 hv=1307778841 ad='5c5cd110'
select condition from cdef$ where rowid=:1
END OF STMT
PARSE #34:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1160715883626944
BINDS #34:
bind 0: dty=11 mxl=16(16) mal=00 scl=00 pre=00 oacflg=18 oacfl2=1 size=16 offset=0
bfp=b75c3c10 bln=16 avl=16 flg=05
value=00005AA0.002A.0001
EXEC #34:c=0,e=66,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1160715883627095
FETCH #34:c=0,e=27,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=1160715883627145

Windows box running 10.2.0.2 64 bit:
*** 2008-08-19 10:54:56.341
(A short delay)
PARSING IN CURSOR #31 len=42 dep=1 uid=0 oct=3 lid=0 tim=3404208472 hv=844002283 ad='89386608'
select condition from cdef$ where rowid=:1
END OF STMT
PARSE #31:c=0,e=58,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3404208468
BINDS #31:
kkscoacd
Bind#0
oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
kxsbbbfp=3b7ad440 bln=16 avl=16 flg=05
value=00008708.0004.0001

Charles Hooper
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc.
user489622

Posts: 1
Registered: 02/21/06
Re: Event 10046 and timestamp
Posted: Sep 30, 2008 8:32 AM   in response to: Leo Anderson in response to: Leo Anderson
Click to report abuse...   Click to reply to this thread Reply
Hello,

I've been struggling with this topic for a few days now, and I think I found an answer.

First: what is the tim value? Cary Millsap states in his book "Optimizing Oracle Performance" that it represents
"the V$TIMER.HSECS value for releases prior to Oracle9i".

This still seems to apply for current releases, as Metalink Article 39817.1 notes:
"tim Timestamp. Pre-Oracle9i, the times recorded by Oracle only have a resolution of 1/100th of a second (10mS). As of Oracle9i some times are available to microsecond accuracy (1/1,000,000th of a second).The timestamp can be used to determine times between points in the trace file. The value is the value in V$TIMER when the line was written. If there are TIMESTAMPS in the file you can use the difference between 'tim' values to determine an absolute time."

Example (taken from a UNIX System running 10g, so we have microsecond resolution here):
first timestamp in tracefile=2008-09-13 03:20:25, first tim=447543130411. The actual seconds are 447543 (rounded).

alter session set nls_date_format='DD.MM.YYYY HH24:MI:SS';
declare
t0 date;
tim0 number := round(floor(447543134861/10E5)); /*** seconds after removing microseconds: 447543 ***/
begin
t0 := to_date('1970-01-01 00:00:00', 'YYYY-MM-DD HH24:MI:SS'); /*** epoch ***/
t0 := t0 + round(tim0/86400); /*** epoch plus days ***/
dbms_output.put_line('tim date: '||t0); /*** show the new date ***/
end;
/

tim date: 06.01.1970 00:00:00

Well this cannot be, since the trace was taken in September 2008. So what's wrong?

If tim is a value from V$TIMER, looking at the Oracle Documentation (10.2) helps understanding this:
http://download.oracle.com/docs/cd/B19306_01/server.102/b14237/dynviews_2168.htm#REFRN30289
"This view lists the elapsed time in hundredths of seconds. Time is measured since the beginning of the epoch, which is operating system specific, and wraps around to 0 again whenever the value overflows four bytes (roughly 497 days)."
(maybe the documentation needs an update about the microseconds as of Oracle 10g).

This explains why you sometimes get strange results if you just take the seconds of the tim value, divide it by 86400 to get the days, and add the result to the epoch date: You cannot be sure if tim/10E5 (Oracle10g) or tim/100 (Oracle9i) is always seconds from epoch, since the value in V$TIMER is reset to 0 after appr. 497 days. It apparently depends on the uptime of your instance how small or big the difference to epoch really is.

So a direct conversion without knowing the difference between tim, epoch and the wallclock is not possible.
But, if you have a timestamp in your tracefiles it can serve as a starting point for futher use while reading a tracefile via an external_table or similar. Example (Oracle 10.2): store the first timestamp from the tracefile in a table as a timestamp and add NUMTODSINTERVAL((current_tim_value - first_tim_value)/10E5, 'SECOND') to it:

SQL> create table t1 (ts timestamp);

Table created.

SQL> insert into t1 values(timestamp '2008-09-12 04:57:10.338000'); /* first timestamp in trace*/

1 row created.

SQL> commit;

Commit complete.

/* (latest tim value - first tim value)/1000000 */
SQL> select ts + numtodsinterval(((377986953662-368834245626)/10E5), 'SECOND') new_timestamp from t1;

NEW_TIMESTAMP

12.09.2008 07:29:43.046036

1 row selected.

best regards,
Stefan Obermeyer
NCDC Midrange Operationsmanagement DBA
EDS, an HP company

Legend
Guru Guru : 2500 - 1000000 pts
Expert Expert : 1000 - 2499 pts
Pro Pro : 500 - 999 pts
Journeyman Journeyman : 200 - 499 pts
Newbie Newbie : 0 - 199 pts
Oracle ACE Director
Oracle ACE Member
Oracle Employee ACE
Helpful Answer (5 pts)
Correct Answer (10 pts)

Point your RSS reader here for a feed of the latest messages in all forums