gethrtime() usage in ORACLE 10g

I don't think there are lot of applications that writes out gethrtime() return value in trace or log files. Oracle is one of them. So, I wrote a perl to convert those values in my previous blog. There are very visible caveats.
  1. It doesn't run on other platforms.
  2. Run it on the same machine you took the trace.
  3. Run it before you reboot. Because gethrtime() counter starts on boot time.
  4. You want to run it right after taking Oracle sql trace. Because:
    1. gethrtime() counter rolls over to 0 after 497 days.
    2. OS timestamp will drift for several reasons. e.g.) ntp kicking in.
Let's see how the perl works on one of my SPARC server.
  1. oracle sql trace output fragment today 
    *** SESSION ID:(491.26184) 2009-07-23 23:25:45.437
=====================
PARSING IN CURSOR #1 len=109 dep=0 uid=65 oct=3 lid=65 tim=3113736335727 hv=2518377154 ad='b9ccd050'
SELECT timestamp, id, version, changeType FROM objchange WHERE timestamp > :1  AND type=:2 ORDER BY timestamp
END OF STMT
*** 2009-07-23 23:25:55.456
WAIT #0: nam='SQL*Net message from client' ela= 8 driver id=1297371904 #bytes=1 p3=0 obj#=-1 tim=3113746119816
    Run it throught the perl. 
    $ perl ~kinoue/oracle.Trace.Tim.pl /tmp/orcl_s000_11620.trc.2
*** SESSION ID:(491.26184) 2009-07-23 23:25:45.437
=====================
PARSING IN CURSOR #1 len=109 dep=0 uid=65 oct=3 lid=65 tim=2009-07-23 23:25:45.43776  hv=2518377154 ad='b9ccd050'
SELECT timestamp, id, version, changeType FROM objchange WHERE timestamp > :1  AND type=:2 ORDER BY timestamp
END OF STMT
*** 2009-07-23 23:25:55.456
WAIT #0: nam='SQL*Net message from client' ela= 8 driver id=1297371904 #bytes=1 p3=0 obj#=-1 tim=2009-07-23 23:25:55.45667
  2. oracle sql trace output fragment from 11 days ago 
    *** SESSION ID:(481.17143) 2009-07-12 04:22:39.236
=====================
PARSING IN CURSOR #6 len=144 dep=0 uid=65 oct=3 lid=65 tim=2118622857650 hv=41747736 ad='b9cb2e10'
SELECT task.id, task.type, name, '', '', summary, '', '', xmlSize  FROM task WHERE task.type='TaskInstance'
and task.attr1='READY' order by name
    Run it throught the perl. 
    *** SESSION ID:(481.17143) 2009-07-12 04:22:39.236
=====================
PARSING IN CURSOR #6 len=144 dep=0 uid=65 oct=3 lid=65 tim=2009-07-12 04:22:29.23621  hv=41747736 ad='b9cb2e10'
SELECT task.id, task.type, name, '', '', summary, '', '', xmlSize  FROM task WHERE task.type='TaskInstance'
and task.attr1='READY' order by name
  3. oracle sql trace output fragment from 21 days ago 
    *** SESSION ID:(492.30132) 2009-07-02 14:26:52.437
=====================
PARSING IN CURSOR #1 len=109 dep=0 uid=65 oct=3 lid=65 tim=1310268562358 hv=2518377154 ad='b9ccd050'
SELECT timestamp, id, version, changeType FROM objchange WHERE timestamp > :1  AND type=:2 ORDER BY timestamp
    Run it throught the perl. 
    *** SESSION ID:(492.30132) 2009-07-02 14:26:52.437
=====================
PARSING IN CURSOR #1 len=109 dep=0 uid=65 oct=3 lid=65 tim=2009-07-02 14:26:34.43783  hv=2518377154 ad='b9ccd050'
SELECT timestamp, id, version, changeType FROM objchange WHERE timestamp > :1  AND type=:2 ORDER BY timestamp
My machine is not set up for ntp client. Yet, OS timestamp seems to constantly drift for certain seconds. Probably, the drift is caused by machine's internal hardware clock.

Posted on: Jul 24, 2009

Posted by: Katsumi Inoue

Category: Sun

Trackback URL: http://blogs.sun.com/LetTheSunShineIn/entry/gethrtime_usage_in_oracle_10g1

Comments:

[Trackback] Seeing Katsumi Inoue blogging about Oracle 10g reporting timestamps using the output from gethrtime() reminded me that I have had on occasion wished I had a log to map hrtime to the current time. As Katsumi points out the output of gethrtime() is...

Posted by The dot in ... --- ... on July 25, 2009 at 12:13 AM JST #

Post a Comment:
  • HTML Syntax: NOT allowed

This blog copyright 2009 by Katsumi Inoue