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.
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 24, 2009 at 05:13 PM JST #

Post a Comment:
  • HTML Syntax: NOT allowed
About

The views expressed on this blog are my own and do not necessarily reflect the views of Oracle.

Search

Archives
« April 2014
SunMonTueWedThuFriSat
  
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
   
       
Today