Monday, April 12, 2010

Converting time values in trace files into wall-clock time

There may be cases where you would like to know the exact wall-clock time when a particular wait-event occurred or the SQL was executed by looking at the trace file.
Oracle captures the wall-clock time in the trace files and represents it in the following format:

AIT #2: nam='SQL*Net message from client' ela= 16445143 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1271092519750890

The value, we are interested in is the last one (
tim=1271092519750890).


The tim value can be converted into wall-clock time by using the following:

Take the first 10 digits, and then:

$date -d @1271092519 +"%m-%d-%Y %T"

Example:
tim=1271092519750890, first 10 characters - 1271092519

$date -d @1271092519 +"%m-%d-%Y %T"

04-12-2010 12:15:19


This could be useful in situations where you would like to find out when a user session completed execution, went back to the client to do some other processing and when it came back to database to execute subsequent SQLs.

BTW, there seems to be a difference in how this value is represented in 11g compared previous versions. I could not get the accurate wall-clock time for a tim value from 10g database.