Oracle 10046 tim, e and ela Values use Nanoseconds/1024 not Microseconds, on some Platforms

From: "Andrew Zitelli" <azitelli@xxxxxxxxx>
To: oracle-l@xxxxxxxxxxxxx
Date: Fri, 30 Mar 2007 18:38:38 -0700
OVERVIEW:
In recent attempts to correlate 10046 extended trace data from Oracle 10.2,
with DTrace data collected under Sun Solaris, I discovered that the tim,
ela and e fields in Oracle trace data are not measured in microseconds.
Under Solaris, they are actually measured in nanoseconds/1024.  In
subsequent testing I found this behavior varies by operating system.
Tests in my facility have shown that Oracle 9.2 and 10.2 under Linux
and Solaris, both record these values in nanoseconds/1024.  Oracle 10.2
under MS Windows records these values in genuine microseconds.
Oracle Note #39817.1, "Interpreting Raw SQL_TRACE and
DBMS_SUPPORT.START_TRACE Output," misleadingly implies that these
times are always recorded in microseconds.

DETAILED DESCRIPTION:
The inconsistency is easily observed under Linux which derives its times
from the function gettimeofday().  This function returns microseconds
since 01 January 1970 00:00:00 UTC.  The following lines were extracted
from a 10046 trace file, from Oracle 9.2.0.6.0 under Linux.

*** SESSION ID:(52.55034) 2007-01-19 09:56:00.761
WAIT #0: nam='SQL*Net message to client' ela=4639 p1=1650815232 p2=1 p3=0
WAIT #0: nam='SQL*Net message from client' ela=27102 p1=1650815232 p2=1 p3=0
=====================
PARSING IN CURSOR #1 len=147 dep=1 uid=0 oct=3 lid=0 tim=1141818516446923

The tim value on the last line, 1141818516446923, does not correspond to
2007-01-19 09:56:00.761 as shown on the first line of the example.  This
value actually corresponds to 2006-03-17 11:48:36, a 10 month discrepancy.
Multiplying 1141818516.446923 by 1024 yields the nanosecond value
1169222160.841649152.  This exactly corresponds to the time
2007-01-19 09:56:00 for the time zone in which the sample was taken.
The 80 millisecond discrepancy between the two measurements is due the
fact that time measurements on the two lines were collected by separate
calls to gettimeofday().  This is clearly evident in the strace file
gathered for this Oracle session.

On Solaris, Oracle derives tim, e and ela values with a call to
gethrtime().  This returns nanoseconds since system reboot so this exact
experiment will not work on Solaris.  If you choose to attempt this
experiment on your own Linux system, remember to adjust the beginning of
epoch (time 0) for your local time zone.  For example, the sample above
came from Texas, 6 hours before UTC so time zero on the corresponding
machine corresponds to 31 December 1969 18:00:00.

The odd time units in use on Linux and Solaris are slightly longer than
1/1000000 second.  The units are actually 1/9765625 second each.  This
interval will not dramatically hinder those using "Method R" or similar a
method to analyze these trace files for performance assessments.  The ratios

of the tim, e and ela values remain unchanged.  The problems arise when
trying to correlate these values with data collected from other sources.
During correlation, the non-standard Oracle values will result in Oracle
working 2.4% longer than we are lead to believe, if units are assumed to
be microseconds.  This will result in 2.4% of Oracle's elapsed time being
unaccounted for, when compared to other data sources.

PROPOSAL FOR A SIMPLE COLLABORATIVE EFFORT:
I have only inspected Oracle versions and ports which are readily
accessible to me.  I would like to expand this to include as many Oracle
versions and ports as possible.  My plan is to publish a simple matrix
showing which Oracle versions and ports display tim, e and
ela in microseconds and which use nanoseconds/1024.

For those interested in helping, I have devised a very simple experiment,
using SQL*Plus from any Oracle account.  The only requirement is one
must have access to the OS directories where 10046 trace files are
written by Oracle.  The experiment takes about 10 minutes, mostly letting
the SL*Plus session sit idle.  I ask that the following SQL commands be
executed from SQL*Plus, with a minimum pause of 5 to 10 minutes as
indicated below.

 SQL> spool trace_test.log
 SQL> alter session set timed_statistics=true
 SQL> alter session set events '10046 trace name context forever, level 8'
 SQL> select systimestamp from dual;

    -- wait approximately 10 minutes --

 SQL> select systimestamp from dual;
 SQL> exit;

I am primarily interested in Oracle 9.x and 10.x.  If someone wants to
gather Oracle 8.1 data from a Linux or Solaris machine, it would be
interesting to see if there is any similar behavior.  Oracle 8.1 and
earlier returned tim, e and ela values in centiseconds.  Under Oracle 8.1
the SELECT statements above will need to be changed as follows:

 SQL> select to_char (sysdate, 'HH24:MI:SS') from dual;

At the conclusion of your experiment, please email me the 10046 trace file,
the spool file (or the two timestamps you queried), and the following
information:

  - Oracle Version (e.g., 9.2.0.4.0, 10.2.0.1.0)
  - Operating System Type and Version (e.g., Solaris 9, HP/UX 11i)
  - OS patch version, if pertinent (e.g., Windows XP Pro, Service Pack 2)
  - Hardware Type when pertinent (e.g., x86 or SPARC for Solaris)
  - Any other comments you think are important.

Please keep this simple.  It is not intended to be much work for anyone.
Please email me the files and information at the following address set
up for this experiment:

  zitelli10046@xxxxxxxxx

Please sent me these results by April 15.  I will summarize the results
and email them back to all participants and those requesting them.

Thank you in advance for all assistance on this.
Oracle 10046 tim, e and ela Values use Nanoseconds/1024 not Microseconds, on some Platforms

Other related posts:
