0

Oracle 10046 trace files contain data like

*** SESSION ID:(501.50681) 2022-08-08T13:27:08.567565+02:00
*** CLIENT ID:() 2022-08-08T13:27:08.567584+02:00
...
WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=10287043490743
...
PARSE #140428862194944:c=204,e=203,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=422997890,tim=10287043504707
EXEC #140428862194944:c=103,e=103,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=422997890,tim=10287043504953
WAIT #140428862194944: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=10287043505039
...

I know my question is almost solved in Convert/replace time from epoch milliseconds... but in my case I don't want to start from "epoch" but from the date displayed just above, say at line with "*** CLIENT ID:... 2022-08-08T13:27:08...".

So - knowing that "tim=10287043490743" approximately equals to Aug 8th at 13:27:08, how could I convert all further occurrences of this microseconds string "tim=....." to a legible date and time format ?

More info about Oracle 10046 trace files structure, let's take INST2_ora_7504.trc file:

[oracle@machine sql]$ ls -l $tf  
-rw-r----- 1 oracle asmadmin 2996974 Aug  8 13:39 /opt/.../rdbms/dbuniq_nam/INST2/trace/INST2_ora_7504.trc

As you can see it was finished being written on Aug 8th at 13:39.
Retrieving timestamp of when it began being written:

[oracle@machine sql]$ grep "CLIENT ID"  $tf
*** CLIENT ID:() 2022-08-08T13:27:08.567584+02:00

First occurrence of timing info:

[oracle@machine sql]$ grep "tim="  $tf|head -1
WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=10287043490743

Last one:

[oracle@machine sql]$  grep "tim="  $tf|tail -1
CLOSE #140428862208536:c=8,e=9,dep=0,type=0,tim=10287767781596

This file contains 28756 lines with "tim=". Under Oracle it's very easy to compute what I want in SQL:

[oracle@machine sql]$ sqlplus / as sysdba

SQL> select to_date('2022-08-08 13:27:08','YYYY-MM-DD HH24:MI:SS')+((10287767781596/24/60/60/1000000) - 
   2 (10287043490743/24/60/60/1000000)) from dual;


TO_DATE('2022-08-08


08/08/2022_13:39:12

See ? Taking last "tim=" value, adding it to timestamp contained in file header, and substracting its equivalent value in microseconds allows you to verify that the filed ended up being written indeed at 13:39 (like 'ls -l' showed above).

But I'd like to do this outside of SQL/Oracle tools...

Thanks.
Regards,
Seb

Seb
  • 1
  • Do you want the values to be time differentials, like "T+123s" or "T+2:03", where "T" refers to the "CLIENT ID" time, or do you want the full date and time displayed? For the former, I would look at using Python and its datetime module (datetime.timedelta objects in particular), for the latter, that is what you would get from doing a conversion against the epoch (so I'm confused about what you want). – t0w0i7ne Aug 10 '22 at 16:17
  • How are you making conversions? The tim=10287043490743 becomes +327953-06-07T04:45:43.000000 if it is assumed to be seconds since epoch or conversely, Aug 8th at 13:27:08 becomes 1659979628. That is a huge difference with what you claim it to be. – QuartzCristal Aug 10 '22 at 17:08
  • To answer t0w0i7ne: I'd like to get your 2nd option: full date-hours-min-secs value displayed. – Seb Aug 11 '22 at 09:01
  • Your /1000000 suggests they are microseconds rather than milliseconds. – Stéphane Chazelas Aug 11 '22 at 09:08
  • Oops - what a blunder, sorry: changed everywhere I still could edit and modify. Thanks for noticing my mistake. – Seb Aug 11 '22 at 09:11
  • To answer QuartzCristal: I once read that these "tim=..." values in microseconds come from internal Oracle view V$TIMER, but I doubt it cause HSECS column value in this view is shorter (10-position digit against 14 in trace files), it therefore contains less information (less details); doc says "V$TIMER displays the elapsed time in hundredths of a second. 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)." – Seb Aug 11 '22 at 09:13

1 Answers1

0

I didn't know the 'date' command under Linux could be handled so easily:

[oracle@machine sql]$ echo "(10287767781596/1000000)-(10287043490743/1000000)"|bc
724

[oracle@machine sql]$ date '+%Y-%m-%dT%T' --date="2022-08-08 13:27:08 CEST + 724 seconds"
2022-08-08T13:39:12

Which is exactly the same result as that which I had in my SQL command above.

Seb
  • 1