RSS Feed

Method R Discussion Group

There are very large values for 'e' and 'ela' in my trace file.
For example:
FETCH #1:c=0,e=9182,p=5,cr=7,cu=0,mis=0,r=85,dep=0,og=4,tim=2190693061
WAIT #1: nam='SQL*Net message from client' ela= 687288424 p1=1413697536 p2=1 p3=0
WAIT #1: nam='SQL*Net message to client' ela= 2 p1=1413697536 p2=1 p3=0
WAIT #1: nam='db file sequential read' ela= 1503457826 p1=5 p2=302656 p3=1
WAIT #1: nam='db file sequential read' ela= 435 p1=5 p2=302731 p3=1
WAIT #1: nam='db file sequential read' ela= 395 p1=5 p2=302732 p3=1
WAIT #1: nam='db file sequential read' ela= 368 p1=5 p2=302733 p3=1
WAIT #1: nam='db file sequential read' ela= 15696 p1=1 p2=295880 p3=1
WAIT #1: nam='db file sequential read' ela= 309 p1=5 p2=302734 p3=1
FETCH #1:c=0,e=2190764181,p=6,cr=8,cu=0,mis=0,r=85,dep=0,og=4,tim=2190764181

Query execute for half an minute. Why e=2190764181?

Yes it is a very strange trace file. For the excerpt you show, the 'tim' clock has advanced 71,120 units between FETCH calls. If you're on Oracle 9 or 10, then that's 0.071120 seconds. ...Which bears no relation to the half-a-minute experience you describe.

Then there's the 1,503.457826-sec (assuming v9+) read call, which I can nearly assure you didn't happen. The 687.288424-second 'SQL*Net message from client' event is entirely plausible (we see that all the time; this could have been an 11.5-minute phone call, for example). But it's very strange that the duration of the '...message from client' call doesn't fit within the 0.071120-second 'tim' clock advance. In thousands of trace files, I don't think I've ever seen that before.

The one thing that does foot in this file is that c + sum(ela) does approximately equal the e value for the second FETCH call.

I've seen really wacky looking read durations before on AIX systems. They've been just plain wrong numbers, but I don't think I've ever learned whether the bug has been with AIX or with the Oracle kernel.

One question: Are you sure that the trace data you're showing here is unadulterated? No missing lines, no changed data values, etc.?

Thank you very much for your answer.
I'm sure that the trace data showing by me here is unadulterated.
This file generate by:

Oracle9i Enterprise Edition Release 9.2.0.8.0 - Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.8.0 - Production
Windows 2000 Version 5.2 Service Pack 1, CPU type 586

There are many other strange lines like these in this file.
File size - 76 KB.
I can send it.
Give me e-mail address, please.

Or better yet:

1)      Click on the Log In -> Profiler Portal Log In link located on the red navigation bar at www.hotsos.com.

2)      Login using your Hotsos web registration ID and password (free registration if you have not already registered at https://secure.hotsos.com/secure/account/register.php).

3)      Next, use the Upload Manager page to upload a zipped 10046 trace file.  You are welcome to upload several traces (zipped and uploaded separately) if you would like. 

4)      Once uploaded, you should see your file on the File Manager page. 

5)      Finally, send me an email that you have completed the upload and I will run your trace through the Profiler. 

6)      I will let you know when your report has run, and you will then have access to the Profiler report from the File Manager page.