In mrskew, can I calculate human readable timestamps from tim?

user_4026394 0
Viewed 134

I'm using mrskew by Method-R to analyze Oracle SQL Trace files.

I want to list all database calls similar to the output of calls.rc
But instead of the value of $tim, I'd print a human readable date format.

Raw data (minimal obfuscated):

*** 2020-11-26 10:06:01.867
*** SESSION ID:(1391.49878) 2020-11-26 10:06:01.867
*** CLIENT ID:() 2020-11-26 10:06:01.867
*** SERVICE NAME:(SYS$USERS) 2020-11-26 10:06:01.867
*** MODULE NAME:(JDBC Thin Client) 2020-11-26 10:06:01.867
*** CLIENT DRIVER:(jdbcthin : 12.2.0.1.0) 2020-11-26 10:06:01.867
*** ACTION NAME:() 2020-11-26 10:06:01.867
...
WAIT #0: nam='SQL*Net message from client' ela= 491 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=12568091328841
=====================
PARSING IN CURSOR #18446744071522016088 len=71 dep=0 uid=88 oct=7 lid=88 tim=12568091329190 hv=2304270232 ad='61e4d11e0' sqlid='5kpbj024phrws'
/*Begin.Work*/
SELECT ...
END OF STMT
PARSE #18446744071522016088:c=147,e=148,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=957996380,tim=12568091329190
...
EXEC #18446744071522016088:c=683,e=11406,p=0,cr=2,cu=11,mis=0,r=1,dep=0,og=1,plh=957996380,tim=12568091341788
CLOSE #18446744071522016088:c=27,e=27,dep=0,type=1,tim=12568091343665
XCTEND rlbk=0, rd_only=0, tim=12568091343769

Current output (compacted for readability):

          END-TIM       LINE       SQL_ID CALL-NAME STATEMENT-TEXT
-----------------------------------------------------------------------------
  12568091.341788         36 5kpbj024phrws EXEC     /*Begin.Work*/ SELECT ...
  12568091.343769         42               XCTEND

Expected output (please don't cricicise my not correct subsecond calculation):

                  END-TIME LINE        SQL_ID CALL-NAME STATEMENT-TEXT  
-----------------------------------------------------------------------
2020-11-26 10:06:01.341788   36 5kpbj024phrws EXEC     /*Begin.Work*/ SELECT ...
2020-11-26 10:06:01.343769   42               XCTEND

I assume I can use POSIX:strftime to format the timestamp properly, but I need a way to generate an epoch timestamp from the timestamp at the begin of the tracefile

*** 2020-11-26 10:06:01.867

and then an offset for each $tim relative to this begin of tracefile.
I hope methodr toolset can provide this. It should be easier for me to explain, when (in human readable form) which activity started.

instrumentation perl oracle
2 Answers

Generating an epoch seconds number from a string date is simple enough. Time::Local has functions to do it.

#!/usr/bin/perl

use strict;
use warnings;
use feature 'say';

use Time::Local 'timelocal_posix';

my $date = '2020-11-26 10:06:01.867';

# Split the date apart
my ($yr, $mon, $day, $hr, $min, $sec, $micro) = split /[- :.]/, $date;

# Note necessary adjustments to month and year
say timelocal_posix($sec, $min, $hr, $day, $mon - 1, $yr - 1900);
user_72310

With the help of comments by @DaveCross and @CaryMillsap my processing is now:

  1. from the tracefile create an intermediate file similar to

    *** 2020-11-26 10:06:01.867

      END-TIM       LINE       SQL_ID CALL-NAME STATEMENT-TEXT
-----------------------------------------------------------------------------
XCTEND tim=12568091341788 e=2 dep=0          36 5kpbj024phrws EXEC     /*Begin.Work*/ SELECT ..
XCTEND tim=12568091343769 e=1 dep=0          42               XCTEND

    using in calls.rc

    sprintf("XCTEND tim=%-20d e=%-5d dep=0 %10d %10d %10d  %13s %-40.40s %-.46s",  $tim*1000000, $line,($e+$ela)*1000000, $parse_id, $exec_id, $sqlid, "· "x$dep.$name.(scalar(@bind)?"(".join(",",@bind).")":""), "· "x$dep.$sql)

  2. modify the result to have somewhere on top

    *** 2020-11-26 10:06:01.867

  3. process this file with mrwhen

  4. get rid of unwantent parts by

     sed -E 's/XCTEND t.{37}//'

In more detail it's documented here.

user_40263940
Related