Skip to Main Content
  • Questions

  • extract execution timestamps from raw tracefile

Breadcrumb

Question and Answer

Tom Kyte

Thanks for the question, Surya.

Asked: September 26, 2008 - 3:39 pm UTC

Last updated: September 30, 2008 - 1:01 pm UTC

Version: 10.2.0

Viewed 10K+ times! This question is

You Asked

Tom,

Greetings.

when you came to the PHLOUG's meeting few months ago, i asked you this question and got some information from you, but need little more further clarification.

I am trying to extract the actual sql statement execution timestamps from the raw tracefile. I found the data element tim=xxxxxxxxxxx a number that seems to represent the timing in micro seconds (one-millionth of a second). Where I am finding difficulty is a reliable way to tie these intervals to the absolute time.

for example here is header from one tracefile.

/u01/app/oracle/admin/CLHBLP/udump/clhblp_ora_1675278.trc
Oracle9i Enterprise Edition Release 9.2.0.4.0 - 64bit Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.4.0 - Production
ORACLE_HOME = /u01/app/oracle/product/9.2.0
System name:    AIX
Node name:      medsg-hbl-midr-1
Release:        3
Version:        5
Machine:        00CDBA9A4C00
Instance name: CLHBLP
Redo thread mounted by this instance: 1
Oracle process number: 17
Unix process pid: 1675278, image: oracle@medsg-hbl-midr-1 (TNS V1-V3)

*** 2008-09-24 09:59:57.624
*** SESSION ID:(16.57786) 2008-09-24 09:59:57.623
=====================
PARSING IN CURSOR #13 len=343 dep=1 uid=0 oct=3 lid=0 tim=1193617966429167 hv=2367942048 ad='41facdf8'


The tim=1193617966429167 is what i am trying to find what it corresponds to. For now, i am tying it the time stamp in the prior lines (*** 2008-09-24 09:59:57.623 or .624), but wondering if there is any other reliable and sql way to get this information (ex. seconds since instance startup, db creation time, last resetlogs time etc.)

Thanks in advance.
- Surya




and Tom said...

you would take the timestamp you see at the top of the trace file and the tim you see right after that - as you have - and they are the "same time". To interpret other tim= records, you would subtract from the first tim= record and then add that to the original trace start time.

The tim= value is a counter from some arbitrary epoch in time. It might be 1-jan-1970 sometimes, but it does not have to be.


Rating

  (3 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

thanks ..

Surya Mandapaka, September 26, 2008 - 5:15 pm UTC

thanks ... tom ..

I tried to verify this on a 9i/10g database, they both seem to origin on 28-NOV-1970 between 09:00 and 11:00 AM.

have a nice day.
Tom Kyte
September 27, 2008 - 11:15 am UTC

and my 11g does different - and different ports can and will have different epochs.

So, please, consider it an arbitrary epoch and base it off of the timestamp if you want the real answer.

I made the connection to 1-jan-1970 since that is the universal "unix" epoch point in time, but it is not assured to be that.

little more ..

Surya Mandapaka, September 27, 2008 - 12:36 pm UTC

Tom,

I was playing around little more yday with multiple tracefiles from the same database for multiple sessions during the same time. like our windows based (VB) application makes about 4 connections and does the work between different sessions (not connection pool type where its completely random which session does what). Now the question i have is can we assume this tim= value to be consistent for the given database. meaning can i combine all sqls from the 4 sessions, sort them by the tim=value to determine the exact sequence of statements across the 4 sessions ??

Last question is "do you think this would be good feature to be added to the traceanalyzer package" ?? from what i see the trca package, this would be one small extra step for the traceanalyzer package, but guess would very helpful to public particularly dealing with third-party canned applications where source code is not available.

Thanks Again,
-Surya
Tom Kyte
September 28, 2008 - 9:42 am UTC

... Now the question i have is can we assume this tim= value to be
consistent for the given database. Now the question i have is can we assume this tim= value to be
consistent for the given database. meaning can i combine all sqls from the 4
sessions, sort them by the tim=value to determine the exact sequence of
statements across the 4 sessions ??
...

The tim= values should align, they come from an OS call - they all use the same OS call

I'm not sure what you could glean from that. You'd have to trace start AND stop times to see anything meaningful

I've never had the need to do this across sessions - what do you hope to get from it (asking in a serious way here)...

sorry if i annoyed you ..

Surya Mandapaka, September 30, 2008 - 11:20 am UTC

Tom,

Sorry if it was annoying.

As said earlier, i started this analysis trying to troubleshoot intermittent hang issue of the VB application i was taking about. the application opens (forks/spawns) 3-4 sessions for the batch processing, each doing bits and pieces of the work. like one session will read the info from some tables, then the other session will write/update other tables and 3rd session will do the audit logging etc. The application has been hanging every once in a while at some orbitary point and the 3rd party application support team requested me to open a ticket with oracle to find out any additional details from oracle side. when i did get a chance to look into the database when it was in the hung state, i saw that the sessions are in idle state waiting for more work from the application. Their application support is not really very good. So i tought i will exact all the sql in the order of execution so they may know where is it getting stuck.

pl. advise if i am going in a wrong direction here.

I have great respect for your wisdom and never meant to waste your time.

with apologies,
- Surya
Tom Kyte
September 30, 2008 - 1:01 pm UTC

you didn't annoy ? I don't know what you read to make you think that? I was asking seriously "why are you doing this, what is the goal"


when it hangs - are any of the session active? If they are all idle - well, then there is something in the application itself - you are not waiting on the database at all.

the tim= numbers are all "sequencable" - you can order things with them across the trace files (they are all consistent with eachother)

You could enable fine grained auditing for these tables (dbms_fga) - then you will get a database view - dba_fga_audit_trail to query and use order by on instead of parsing trace files.
more

Connor and Chris don't just spend all day on AskTOM. You can also catch regular content via Connor's blog and Chris's blog. Or if video is more your thing, check out Connor's channel and Chris's channel from their Youtube channels. And of course, keep up to date with AskTOM via the official twitter account.

More to Explore

VLDB

If you are new to partitioning, check out Connor McDonald's introduction series here.

VLDB

Documentation set on VLDB and Partitioning.