Timestamp in the trace files
Mladen Gogala
I am analyzing a trace file and the developer asked me when has this
event taken place:
=====================
PARSING IN CURSOR #3 len=159 dep=0 uid=141 oct=3 lid=141
tim=1233122414291746 hv=3402358638 ad='9a174550'
select folderarti0_.segment# as col_0_0_, folderarti0_.FOLDER# as
col_1_0_ from FOLDER_ARTICLES folderarti0_ where folderarti0_.segment# in
(:1 , :2 , :3 , :4)
END OF STMT
In other words, how can I convert the "tim" field into time and date?
Mladen Gogala
Please ignore. I figured it out. The "tim" field represents the
difference in microseconds. It's not the real time.That should be an
improvement request that one would have to send to Oracle.
Paulie
> > tim=1233122414291746
> > In other words, how can I convert the "tim" field into time and date?
> Please ignore. I figured it out. The "tim" field represents the
> difference in microseconds. It's not the real time.That should be an
> improvement request that one would have to send to Oracle.
How old is this developer? What is the database and OS?
I'm really very impressed with this statistic because apparently
some process has been running flawlessly on that machine
for more than 39 years (1233122414/60/60/24/365 ~= 39.1).
Paul...
Jonathan Lewis
"Mladen Gogala" <n...@email.here.invalid> wrote in message
news:pan.2010.01...@email.here.invalid...
Isn't it (often) the time in microseconds since the machine started ?
I believe I've also seen cases on older version, and different
platforms of it being
time in nanoseconds,
and time since
instance started
1-Jan-1970
--
Regards
Jonathan Lewis
http://jonathanlewis.wordpress.com
Maxim Demenko
Mladen Gogala
This is not really helpful. The application has run on 05-Jan-2009. Here
is what I get when I try using "seconds from 1970":
Copyright 1991-1994, 1997, 1998, 2000, 2004, 2006 Free Software
Foundation, Inc.
This is free software with ABSOLUTELY NO WARRANTY.
For details type `warranty'.
1233122401969823/1000000
1233122401
scale=2
1233122401969823/1000000
1233122401.96
1233122402
1233122402
mgogala@nycwxp2622:~$ perl -e '@dt=localtime(1233122402); printf("%d.%d.%d
\n",$dt[4],$dt[3],$dt[5]);'
0.28.109
The result is January 28th, 2009, which is almost a year off.
Steve Howard
> 1233122401.96
> 1233122402
> 1233122402
> mgogala@nycwxp2622:~$ perl -e '@dt=localtime(1233122402); printf("%d.%d.%d
> \n",$dt[4],$dt[3],$dt[5]);'
> 0.28.109
>
> The result is January 28th, 2009, which is almost a year off.
>
> --http://mgogala.byethost5.com
I wrote in Python something to do this that isn't perfect, but is
close. It's actually pretty cheezy, too.
Basically, get the first time on the trace file, and that becomes your
baseline...
"""
*** ACTION NAME:() 2009-10-01 09:00:01.757
*** MODULE NAME:(sqlplus@oh1xpwcdb01 (TNS V1-V3)) 2009-10-01
09:00:01.757
*** SERVICE NAME:(SYS$USERS) 2009-10-01 09:00:01.757
*** SESSION ID:(1212.19284) 2009-10-01 09:00:01.757
"""
...then get the first "tim=" value, and assume no time has transpired
between the time printed above and this first time. Yeah, I said it
was cheezy :)
Diff that tim= and all that follow, and add to the original time
printed above. It will be within less than a second, anyway, which is
usually close enough.
I have been messing around with a 10046 trace parser that does this
kind of stuff for a year or so, and it still isn't finished, but I
have used what I have and it has been very valuable. If someone wants
a copy, let me know and I will upload it.
Maxim Demenko
How that? In the first link i supplied, was suggested, on linux and
solaris tim values are in nanoseconds/1024. This suggestion fits
perfectly in your example:
SQL> select date '1970-01-01' + (1233122414291746 * 1024 * 1e-9 /60/60/24 )
2 from dual;
DATE'1970-01-01'+(1
-------------------
05.01.2010 18:49:12
Best regards
Maxim
Maxim Demenko
> On 06.01.2010 20:27, Mladen Gogala wrote:
>> On Wed, 06 Jan 2010 19:37:14 +0100, Maxim Demenko wrote:
>>
>>> On 06.01.2010 19:02, Mladen Gogala wrote:
>>>> On Wed, 06 Jan 2010 17:40:43 +0000, Mladen Gogala wrote:
>>>>
>>>>> I am analyzing a trace file and the developer asked me when has this
>>>>> event taken place:
>>>>>
>>>>> =====================
>>>>> PARSING IN CURSOR #3 len=159 dep=0 uid=141 oct=3 lid=141
>>>>> tim=1233122414291746 hv=3402358638 ad='9a174550' select
>>>>> folderarti0_.segment# as col_0_0_, folderarti0_.FOLDER# as col_1_0_
>>>>> from FOLDER_ARTICLES folderarti0_ where folderarti0_.segment# in (:1 ,
>>>>> :2 , :3 , :4)
>>>>> END OF STMT
>>>
>>
>> is what I get when I try using "seconds from 1970":
>> The result is January 28th, 2009, which is almost a year off.
>>
>
> DATE'1970-01-01'+(1
> -------------------
> 05.01.2010 18:49:12
>
>
> Best regards
>
> Maxim
>
Sorry, of course, i am interpreting your words like it better suit my
needs ;-)
But either your meant to say "The application has run on 05-Jan-2010" -
in that case my previous post still applies, or it run indeed on
05-Jan-2009 and my math is wrong, but then it is unclear with "The
result is January 28th, 2009, which is almost a year off".
Best regards
Maxim
Steve Howard
It doesn't work for me either...
SQL> !date
Wed Jan 6 16:44:47 EST 2010
SQL> alter session set events '10046 trace name context forever, level
1';
Session altered.
SQL> select 1 from dual;
1
----------
1
SQL> !ls -lrt | tail -1
-rw-r----- 1 oracle dba 1923 2010-01-06 16:45 wcasprod_ora_3974.trc
SQL> !grep PARSE wcasprod_ora_3974.trc
PARSE
#3:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1233217089752915
PARSE
#2:c=0,e=1029,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1233217094339231
PARSE
#3:c=0,e=39,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1233217094340214
SQL> select to_date('1970-01-01','YYYY-MM-DD') + (&1/1000000) / 86400
from dual
2 /
Enter value for 1: 1233217089752915
TO_DATE('1970-01-01','YYYY-MM
-----------------------------
29-JAN-2009 08:18:10
SQL>
Mladen Gogala
> Sorry, of course, i am interpreting your words like it better suit my
> needs ;-)
> But either your meant to say "The application has run on 05-Jan-2010" -
> in that case my previous post still applies, or it run indeed on
> 05-Jan-2009 and my math is wrong, but then it is unclear with "The
> result is January 28th, 2009, which is almost a year off".
>
>
> Best regards
>
> Maxim
Maxim, you helped me a lot! It works now. Here is the result, written in
The algorithm is yours, I just had to apply it properly. Thanks again
for your help. I must be getting senile these days.
#!/usr/bin/perl -w
use strict;
sub cnv_tim($);
sub cnv_tim($) {
my $A = shift;
my ( $sec, $min, $hr, $dd, $mm, $yr ) =
localtime( ( $A * 1024 ) / 1000000000 );
$yr += 1900;
$mm++;
my $str = sprintf( "%d-%d-%d %d:%d:%d\n", $yr, $mm, $dd, $hr, $min,
$sec );
return ($str);
}
map { print "tim=$_ --> ", cnv_tim($_); } @ARGV;
Here is how to run it:
mgogala@nycwxp2622:/tmp$ ./ttt 1233122413959653
tim=1233122413959653 --> 2010-1-5 13:49:11
You can put as many "tim" timestamps on the command line as necessary,
the script will convert them all, one line per timestamp. Some people
object to my function declarations but I used to program in C and have
carried over some habits.
Steve Howard
I think I found the discrepancy, the 1024 mackes the difference.
If this is true, then the time is not truly quoted in microseconds (as
Oracle documents it) in the trace file?
Maxim Demenko
I'm glad, it works for you.
The credit goes of course to Andrew Zitelli, i didn't participate in his
test, but tested his assumption a couple of times on systems i had
access to - and it seems to be the correct rule.
@Steve
i agree, it seems, the official documentation is incomplete, keep in
mind the differences between solaris/linux and windows (and ...) platforms.
Best regards
Maxim
Steve Howard
This is the best news I have heard this week. Thanks!
joel garry
I did participate, but totally forgot until you posted this, though it
sounded familiar... :-)
>
> @Steve
> i agree, it seems, the official documentation is incomplete, keep in
> mind the differences between solaris/linux and windows (and ...) platforms.
>
Not to mention changes and bugs over time, so to speak.
jg
--
@home.com is bogus.
"• Prevent privileged IT staff from accessing the data they are
charged with managing" - Roxana Bradescu Senior Director, Oracle
Database Security Product Marketing