A question about interpreting 10046 event trace file
nirav
I need help to understand and interpret the output of 10046 trace file
(with level 8 ). The problem that we are trying to solve is that: in a
batch process where thousands of inserts are being done, at some point
application hangs - more correctly, transaction time out occurs. The
developers say that: it is the because soemthing happening at the
database level and we are analyzing that issue, for that this is a
portion of the trace file:
<Query X>
call count cpu elapsed disk query
current rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 1 0.00 0.00 0 0
0 0
Execute 7 0.01 0.00 0 0
0 0
Fetch 14 0.00 0.00 0 63
0 70
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 22 0.01 0.00 0 63
0 70
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer goal: CHOOSE
Parsing user id: 933
Rows Row Source Operation
------- ---------------------------------------------------
50 SORT UNIQUE
50 NESTED LOOPS OUTER
40 INDEX RANGE SCAN PK_TABLE1 (object id 1581385)
30 TABLE ACCESS BY INDEX ROWID TABLE2
30 INDEX RANGE SCAN NK3_TABLE2 (object id 1581563)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total
Waited
---------------------------------------- Waited ----------
------------
SQL*Net message to client 15
0.00 0.00
SQL*Net message from client 14
29.35 57.40
********************************************************************************
It is seen from the trace that maximum wait is "SQL*Net message from
the client (54 seconds). In this regard, my question is:
1) Is the <Query X> responsible for this wait? or is the next query in
the trace file after this <Query X>, responsible for this ?
2) Developers are asking that where or in what portion of the code
should they look to investigate? (based on trace file, they expect me
to tell them that.) - Now from the trace file, I found the maximum
wait is in the portion copied above. so in that case does it mean that
-
a) the <Query X> is reponsible for the wait ? or the next query in
trace file just after the <Query X> is responsible or the application
code somewhere around <Query X> is responsible?
With thanks,
Nirav
Charles Hooper
>
> It is seen from the trace that maximum wait is "SQL*Net message from
> the client (54 seconds). In this regard, my question is:
>
> 1) Is the <Query X> responsible for this wait? or is the next query in
> the trace file after this <Query X>, responsible for this ?
>
> 2) Developers are asking that where or in what portion of the code
> should they look to investigate? (based on trace file, they expect me
> to tell them that.) - Now from the trace file, I found the maximum
> wait is in the portion copied above. so in that case does it mean that
> -
> a) the <Query X> is reponsible for the wait ? or the next query in
> trace file just after the <Query X> is responsible or the application
> code somewhere around <Query X> is responsible?
>
> With thanks,
> Nirav
You are looking at the TKPROF output for the trace file, which
summarizes the content of the trace file. "SQL*Net message from
client" is a wait event that indicates that the database is waiting
for the next request from the client (the application).
You will likely want to look at the raw trace file text using a text
editor. In the following example:
1. Turned on a 10046 trace at level 8
2. Waited 30 seconds
3. Selected the current date/time from dual
4. Waited 20 seconds
5. Selected tomorrow's date from dual
6. Waited 15 seconds
7. Disabled tracing.
A portion of the trace file looks like this (this is a 10.2.0.2 trace
file):
----
WAIT #2: nam='SQL*Net message from client' ela= 30189669 driver
id=1413697536 #bytes=1 p3=0 obj#=571 tim=462345302896
{note the 30 second delay in the above)
=====================
PARSING IN CURSOR #3 len=24 dep=0 uid=32 oct=3 lid=32 tim=462345305205
hv=124468195 ad='4ef97594'
SELECT SYSDATE FROM DUAL
END OF STMT
PARSE
#3:c=0,e=1543,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=462345305199
EXEC #3:c=0,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=462345306252
WAIT #3: nam='SQL*Net message to client' ela= 4 driver id=1413697536
#bytes=1 p3=0 obj#=571 tim=462345306463
FETCH
#3:c=0,e=73000,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=462345379675
WAIT #3: nam='SQL*Net message from client' ela= 30603 driver
id=1413697536 #bytes=1 p3=0 obj#=571 tim=462345410692
FETCH #3:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=462345410960
WAIT #3: nam='SQL*Net message to client' ela= 3 driver id=1413697536
#bytes=1 p3=0 obj#=571 tim=462345411158
WAIT #3: nam='SQL*Net message from client' ela= 19908046 driver
id=1413697536 #bytes=1 p3=0 obj#=571 tim=462365319398
{note the nearly 20 second delay in the above)
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0
time=10 us)'
=====================
PARSING IN CURSOR #1 len=26 dep=0 uid=32 oct=3 lid=32 tim=462365321144
hv=4014109308 ad='5254f394'
SELECT SYSDATE+1 FROM DUAL
END OF STMT
PARSE #1:c=0,e=705,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=462365321140
EXEC #1:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=462365322112
WAIT #1: nam='SQL*Net message to client' ela= 4 driver id=1413697536
#bytes=1 p3=0 obj#=571 tim=462365322311
FETCH #1:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=462365322526
WAIT #1: nam='SQL*Net message from client' ela= 280 driver
id=1413697536 #bytes=1 p3=0 obj#=571 tim=462365323013
FETCH #1:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=462365323223
WAIT #1: nam='SQL*Net message to client' ela= 2 driver id=1413697536
#bytes=1 p3=0 obj#=571 tim=462365323428
WAIT #1: nam='SQL*Net message from client' ela= 15193355 driver
id=1413697536 #bytes=1 p3=0 obj#=571 tim=462380516973
{note the 15 second delay in the above)
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0
time=7 us)'
=====================
PARSING IN CURSOR #2 len=55 dep=0 uid=32 oct=42 lid=32
tim=462380585505 hv=524428051 ad='0'
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF'
END OF STMT
PARSE
#2:c=0,e=67552,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=462380585499
EXEC #2:c=0,e=61,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=462380586594
----
Manually reviewing the 10046 trace file also exposes the raw
statistics as they happened:
c=0,e=36,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1
Charles Hooper
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc.
hpuxrac
snip
> > I need help to understand and interpret the output of 10046 trace file
> > (with level 8 ). The problem that we are trying to solve is that: in a
> > batch process where thousands of inserts are being done, at some point
> > application hangs - more correctly, transaction time out occurs. The
> > developers say that: it is the because soemthing happening at the
> > database level and we are analyzing that issue, for that this is a
> > portion of the trace file:
Application hangs and database time outs must be understood from the
side of the application that is experiencing problems.
That being said, Cary Millsap has an excellent book "pretty much all
about" how to use raw trace data and you should pick up and read
"Optimizing Oracle Performance". Personally I recommend looking at
the free utility orasrp which does a much better job ( imho ) than
tkprof at breaking out important info from a 10046 trace. Cary
Millsap's company hotsos does sell a commercial version of a resource
profiler ( which is apparently very good ) but orasrp to me does all
that is required.
Do you have any locking or latching issues when the application hangs
are being experienced?
What kind of connection type is the application using?
What verison of oracle and running on what platform?
nirav
> are being experienced?
>
> What kind of connection type is the application using?
>
> What verison of oracle and running on what platform?
Thank you both for your valuable inputs. Yes, I read the chapter from
Carry Milsap's book and with that , I am getting clue on reading the
raw trace file and get the info. required. We are on oracle 9.2.0.7 on
solaris. about connection type I do not know much actually. We do not
have any latch issue when the application hangs but a few tables to
get locked when the hang occurs.
Again thanks for the valuable pointers...
Nirav