7 Replies Latest reply: Oct 4, 2008 2:36 AM by 492625 RSS

    Event 10046 and timestamp

    595286
      Hi,

      When setting event 10046 for tuning purpose, I'd like to get the timestamp to compare with other logs (application, OS, ...)

      Is it possible ?

      How to convert "tim=8317892534" in readable date/time ?

      Thanks,

      Leo.
        • 1. Re: Event 10046 and timestamp
          riedelme
          You can't easily convert the tim value because it does not reference a real time. You could try to simulate this by corrdinating it with a starting time and adding ahead but I'm doubtful about how accurate that would be
          • 2. Re: Event 10046 and timestamp
            Charles Hooper
            Leo,

            The answer will depend on the operating system and Oracle version. Prior to Oracle 9i, it is possible to divide the tim= values by 100 to convert the number to seconds. Starting with Oracle 9i, it is possible to divide the tim= values by 1000000 to convert the number to seconds. If I remember correctly, on Unix/Linux, the tim= value may be used to determine the number of seconds elapsed since the Unix epoch, which is midnight Jan 1, 1970. On Windows, it is not quite as clear. Even on 64 bit Oracle 10g R2 running on Windows, the value of tim= may wrap around during the capture of the trace, as if it were a 32 bit unsigned integer (2^32 = 4294967296 = wrap roughly every 4294.967296 seconds).

            The start of the trace file should contain the trace start time:
            Ex: Tue Aug 19 08:16:14 2008
            Periodically, you should find Oracle emitting the current date and time in the trace file:
            Ex: *** 2008-08-19 08:16:25.513

            Hopefully, the above will help.

            Charles Hooper
            IT Manager/Oracle DBA
            K&M Machine-Fabricating, Inc.
            • 3. Re: Event 10046 and timestamp
              595286
              Hi,

              were did you get those informations about the unix/windows differences, the factor used for converting ?

              Are the results could be considered as definitive ?

              Thanks,

              Leo.
              • 4. Re: Event 10046 and timestamp
                P.Forstmann
                About Oracle 9 you can find some info in Optimizing Oracle Performance book.

                Metalink note Interpreting Raw SQL_TRACE and DBMS_SUPPORT.START_TRACE output gives some limited details.
                • 5. Re: Event 10046 and timestamp
                  595286
                  "limited details".... that's the exact words ! :p
                  • 6. Re: Event 10046 and timestamp
                    Charles Hooper
                    were did you get those informations about the
                    unix/windows differences, the factor used for
                    converting ?

                    Are the results could be considered as definitive ?
                    I have worked with 10046 trace files since reading Cary Millsap's "Optimizing Oracle Performance" book shortly after the book was released - it is quite amazing the amount of detail that may be extracted from such files. If you have access to that book, take a look at the middle of page 79 for an explanation of the tim= meaning. It is a bit frustrating attempting to time sequence trace files generated on Windows platforms, especially when the tim values wrap around, where a tim value further down the trace file is smaller than the current line.

                    There are other sources for various bits and pieces of information that may be used to help decode 10046 trace files, but sometimes it is hard to determine which sources are correct, so it helps to be willing to experiment. Message threads that may be of interest:
                    http://www.freelists.org/archives/oracle-l/03-2004/msg03083.html
                    http://www.freelists.org/archives/oracle-l/03-2007/msg01119.html
                    http://www.jlcomp.demon.co.uk/faq/time_unit.html

                    The second and third of the above links indicates that powers of 2 (rather than powers of 10) may also be a factor on some platforms.

                    Samples that show the differences in tim= values between Linux and Windows:
                    Linux box running 9.2.0.4:
                    *** 2007-08-31 11:11:04.729
                    PARSING IN CURSOR #34 len=42 dep=1 uid=0 oct=3 lid=0 tim=1160715883626949 hv=1307778841 ad='5c5cd110'
                    select condition from cdef$ where rowid=:1
                    END OF STMT
                    PARSE #34:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1160715883626944
                    BINDS #34:
                    bind 0: dty=11 mxl=16(16) mal=00 scl=00 pre=00 oacflg=18 oacfl2=1 size=16 offset=0
                       bfp=b75c3c10 bln=16 avl=16 flg=05
                       value=00005AA0.002A.0001
                    EXEC #34:c=0,e=66,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1160715883627095
                    FETCH #34:c=0,e=27,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=1160715883627145
                    Windows box running 10.2.0.2 64 bit:
                    *** 2008-08-19 10:54:56.341
                    (A short delay)
                    PARSING IN CURSOR #31 len=42 dep=1 uid=0 oct=3 lid=0 tim=3404208472 hv=844002283 ad='89386608'
                    select condition from cdef$ where rowid=:1
                    END OF STMT
                    PARSE #31:c=0,e=58,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3404208468
                    BINDS #31:
                    kkscoacd
                    Bind#0
                      oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
                      oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
                      kxsbbbfp=3b7ad440  bln=16  avl=16  flg=05
                      value=00008708.0004.0001
                    Charles Hooper
                    IT Manager/Oracle DBA
                    K&M Machine-Fabricating, Inc.
                    • 7. Re: Event 10046 and timestamp
                      492625
                      Hello,

                      I've been struggling with this topic for a few days now, and I think I found an answer.

                      First: what is the tim value? Cary Millsap states in his book "Optimizing Oracle Performance" that it represents
                      "the V$TIMER.HSECS value for releases prior to Oracle9i".

                      This still seems to apply for current releases, as Metalink Article 39817.1 notes:
                      "tim Timestamp. Pre-Oracle9i, the times recorded by Oracle only have a resolution of 1/100th of a second (10mS). As of Oracle9i some times are available to microsecond accuracy (1/1,000,000th of a second).The timestamp can be used to determine times between points in the trace file. The value is the value in V$TIMER when the line was written. If there are TIMESTAMPS in the file you can use the difference between 'tim' values to determine an absolute time."

                      Example (taken from a UNIX System running 10g, so we have microsecond resolution here):
                      first timestamp in tracefile=2008-09-13 03:20:25, first tim=447543130411. The actual seconds are 447543 (rounded).

                      alter session set nls_date_format='DD.MM.YYYY HH24:MI:SS';
                      declare
                      t0 date;
                      tim0 number := round(floor(447543134861/10E5)); /*** seconds after removing microseconds: 447543 ***/
                      begin
                      t0 := to_date('1970-01-01 00:00:00', 'YYYY-MM-DD HH24:MI:SS'); /*** epoch ***/
                      t0 := t0 + round(tim0/86400); /*** epoch plus days ***/
                      dbms_output.put_line('tim date: '||t0); /*** show the new date ***/
                      end;
                      /

                      tim date: 06.01.1970 00:00:00

                      Well this cannot be, since the trace was taken in September 2008. So what's wrong?

                      If tim is a value from V$TIMER, looking at the Oracle Documentation (10.2) helps understanding this:
                      [http://download.oracle.com/docs/cd/B19306_01/server.102/b14237/dynviews_2168.htm#REFRN30289]
                      "+This view lists the elapsed time in hundredths of seconds. 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).+"
                      (maybe the documentation needs an update about the microseconds as of Oracle 10g).

                      This explains why you sometimes get strange results if you just take the seconds of the tim value, divide it by 86400 to get the days, and add the result to the epoch date: You cannot be sure if tim/10E5 (Oracle10g) or tim/100 (Oracle9i) is always seconds from epoch, since the value in V$TIMER is reset to 0 after appr. 497 days. It apparently depends on the uptime of your instance how small or big the difference to epoch really is.

                      So a direct conversion without knowing the difference between tim, epoch and the wallclock is not possible.
                      But, if you have a timestamp in your tracefiles it can serve as a starting point for futher use while reading a tracefile via an external_table or similar. Example (Oracle 10.2): store the first timestamp from the tracefile in a table as a timestamp and add NUMTODSINTERVAL((current_tim_value - first_tim_value)/10E5, 'SECOND') to it:

                      SQL> create table t1 (ts timestamp);

                      Table created.

                      SQL> insert into t1 values(timestamp '2008-09-12 04:57:10.338000'); /* first timestamp in trace*/

                      1 row created.

                      SQL> commit;

                      Commit complete.

                      /* (latest tim value - first tim value)/1000000 */
                      SQL> select ts + numtodsinterval(((377986953662-368834245626)/10E5), 'SECOND') new_timestamp from t1;

                      NEW_TIMESTAMP
                      ---------------------------------------------------------------------------
                      12.09.2008 07:29:43.046036

                      1 row selected.


                      best regards,
                      Stefan Obermeyer
                      NCDC Midrange Operationsmanagement DBA
                      EDS, an HP company