Missing time in 10046 trace file

  • From: Paul Fitzgerald <pfitzger_au@xxxxxxxxx>
  • To: Oracle-L <oracle-l@xxxxxxxxxxxxx>
  • Date: Thu, 30 Sep 2004 15:32:58 -0700 (PDT)

All,
  We had a database production problem yesterday where the system was
maxed out at 100% CPU (ENV = AIX 4.3 Websphere 4.3 ORCL 8.1.7.4).  Upon
a quick investigation of the v$session_wait table it was apparent that
nearly all session (approx 40) were waiting on "latch free".  I traced
a problem session with a 10046 level 12 and reviewed the trace file.  

This is where I started to get confused.  The ela times reported for
the latch free waits were only single digit centiseconds yet I saw
these sessions waiting a lot longer than that to return a result.  I do
understand that Oracle will put out a trace line beginning with ***
when a wait event does not return in a certain amount of time. These
can be seen in the 10046 between latch free waits.  By subtracting the
tim value of the FETCH 2276365740 from the time value of the EXEC
2276356674 I get approx 90 seconds (9066 centi-secs) which is nowhere
close to adding all the ela's of the waits (48 centi-secs).  Am I
looking at what they call unmeasured/unaccounted-for time?

I ran a tkprof on the trace file and it reported to me what I expected
and what the users were complaining about in elapsed times: avg 59 secs
per exec (total elapsed 1260.59 / 23 exec times).  Another curious
observation was when I ran the stmt in sqlplus with timing on and using
the binds from the trace file it returned within subseconds.
What was I missing?

P.S. - I do know that this query was at fault as it was
tuned/rewritten/tested and put back into prod giving excellent response
times via the websphere app.

10046 trace file snippet
========================
PARSING IN CURSOR #4 len=435 dep=0 uid=143 oct=3 lid=143 tim=2276356674
hv=3955680513 ad='73a643e8'
[stmt snipped] 
END OF STMT
EXEC #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=2276356674
WAIT #4: nam='latch free' ela= 5 p1=2064350944 p2=66 p3=0
*** 2004-09-30 10:50:06.839
WAIT #4: nam='latch free' ela= 3 p1=2064904804 p2=66 p3=0
*** 2004-09-30 10:50:24.172
WAIT #4: nam='latch free' ela= 4 p1=2065641112 p2=66 p3=0
WAIT #4: nam='latch free' ela= 4 p1=2065122004 p2=66 p3=0
WAIT #4: nam='latch free' ela= 1 p1=2065122004 p2=66 p3=1
WAIT #4: nam='latch free' ela= 1 p1=2065122004 p2=66 p3=2
WAIT #4: nam='latch free' ela= 4 p1=2065122004 p2=66 p3=3
*** 2004-09-30 10:50:49.098
WAIT #4: nam='latch free' ela= 2 p1=2063688484 p2=66 p3=0
WAIT #4: nam='latch free' ela= 1 p1=2063688484 p2=66 p3=1
WAIT #4: nam='latch free' ela= 1 p1=2063688484 p2=66 p3=2
WAIT #4: nam='latch free' ela= 4 p1=2063688484 p2=66 p3=3
WAIT #4: nam='latch free' ela= 7 p1=2065373956 p2=66 p3=0
*** 2004-09-30 10:51:16.321
WAIT #4: nam='latch free' ela= 11 p1=2064824440 p2=66 p3=0
WAIT #4: nam='SQL*Net message to client' ela= 0 p1=675562835 p2=1 p3=0
FETCH
#4:c=684,e=9066,p=0,cr=18681,cu=0,mis=0,r=1,dep=0,og=4,tim=2276365740
WAIT #4: nam='SQL*Net message from client' ela= 7 p1=675562835 p2=1
p3=0
WAIT #4: nam='SQL*Net message to client' ela= 0 p1=675562835 p2=1 p3=0
WAIT #4: nam='SQL*Net message from client' ela= 1 p1=675562835 p2=1
p3=0

tkprof snippet:
===============
[stmt snipped]

call     count       cpu    elapsed       disk      query    current   
    rows
------- ------  -------- ---------- ---------- ---------- ---------- 
----------
Parse        0      0.00       0.00          0          0          0   
       0
Execute     23      0.01       0.09          0          0          0   
       0
Fetch       23    149.51    1260.59          0     424648          0   
      23
------- ------  -------- ---------- ---------- ---------- ---------- 
----------
total       46    149.52    1260.68          0     424648          0   
      23

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 143


                
__________________________________
Do you Yahoo!?
Yahoo! Mail - 50x more storage than other providers!
http://promotions.yahoo.com/new_mail
--
//www.freelists.org/webpage/oracle-l

Other related posts: