Re: A question about interpreting 10046 event trace file
Date: Sun, 6 Jan 2008 05:47:17 -0800 (PST)
Message-ID: <7f6a57be-8b56-4a5e-9c30-9e5cfa70bca2@d21g2000prf.googlegroups.com>
On Jan 6, 5:22 am, nirav <shiva..._at_gmail.com> wrote:
> Hi,
>
> 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
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.
Received on Sun Jan 06 2008 - 07:47:17 CST