Missing time in 10046 trace file

From: Paul Fitzgerald <pfitzger_au_at_yahoo.com>
Date: Thu, 30 Sep 2004 15:32:58 -0700 (PDT)
Message-ID: <20040930223258.36715.qmail@web52907.mail.yahoo.com>

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

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

Received on Thu Sep 30 2004 - 17:28:31 CDT