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

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_at_gmail.com

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.

--
http://www.freelists.org/webpage/oracle-l