Re: orasrp SQL*Net message to client as non-idle event
- From: Karl Arao <karlarao@xxxxxxxxx>
- To: egorst@xxxxxxxxx
- Date: Mon, 8 Feb 2010 08:30:00 +0800
Hi Egor,
How about this one.. I have one long "SQL*Net message from client" at
the end that took 14 seconds which constituted 42% of the Statement
Flat Profile.
Event Name% TimeSecondsCalls- Time per Call -AvgMinMax
----------------------------------------------------------------------------------------
PX Deq: Execute Reply 56.1%18.5378s7830.0237s0.0000s1.9955s
<---- 56.1% (18 sec)
SQL*Net message from client 42.7%14.1206s27.0603s0.0004s14.1202s
<----- 42.7% (14.12 sec) but only have 2 long calls
PX Deq: Signal ACK0.4%0.1394s1130.0012s0.0000s0.0996s
FETCH calls [CPU]0.2%0.0781s20.0391s0.0000s0.0781s
PX Deq Credit: send blkd0.2%0.0758s2070.0004s0.0000s0.0179s
os thread startup0.2%0.0517s340.0015s0.0000s0.0020s
PX Deq: Parse Reply0.1%0.0282s280.0010s0.0000s0.0246s
EXEC calls [CPU]0.0%0.0156s10.0156s0.0156s0.0156s
PX Deq Credit: need buffer0.0%0.0108s330.0003s0.0000s0.0075s
PX Deq: Join ACK0.0%0.0018s230.0001s0.0000s0.0015s
PX qref latch0.0%0.0000s100.0000s0.0000s0.0000s
SQL*Net message to client0.0%0.0000s20.0000s0.0000s0.0000s
PARSE calls [CPU]0.0%0.0000s10.0000s0.0000s0.0000s
Total100.0%33.0598s
Below is the snippet of the raw trace:
PARSING IN CURSOR #2 len=14969 dep=0 uid=56 oct=3 lid=56
tim=3065029088 hv=2270366289 ad='fd7e2568'
... output snipped ...
WAIT #2: nam='PX Deq: Execute Reply' ela= 2 sleeptime/senderid=10
passes=1 p3=0 obj#=-1 tim=3084910884
WAIT #2: nam='PX Deq: Execute Reply' ela= 1 sleeptime/senderid=10
passes=1 p3=0 obj#=-1 tim=3084911409
WAIT #2: nam='PX Deq: Execute Reply' ela= 4 sleeptime/senderid=200
passes=1 p3=0 obj#=-1 tim=3084911456
WAIT #2: nam='PX Deq: Execute Reply' ela= 48 sleeptime/senderid=200
passes=2 p3=0 obj#=-1 tim=3084911524
WAIT #2: nam='PX Deq: Execute Reply' ela= 1 sleeptime/senderid=10
passes=1 p3=0 obj#=-1 tim=3084912006
FETCH #2:c=78125,e=19702325,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=3084912596
WAIT #2: nam='SQL*Net message from client' ela= 376 driver
id=1111838976 #bytes=1 p3=0 obj#=-1 tim=3084913221 <---- 1st wait
WAIT #2: nam='PX Deq: Signal ACK' ela= 3 sleeptime/senderid=0 passes=1
p3=0 obj#=-1 tim=3084913408
*** 2010-02-02 13:50:51.343
WAIT #2: nam='PX Deq: Signal ACK' ela= 99563 sleeptime/senderid=10
passes=2 p3=0 obj#=-1 tim=3085013006
WAIT #2: nam='PX Deq: Signal ACK' ela= 23494 sleeptime/senderid=10
passes=3 p3=0 obj#=-1 tim=3085036560
WAIT #2: nam='PX Deq: Signal ACK' ela= 2 sleeptime/senderid=0 passes=1
p3=0 obj#=-1 tim=3085036593
WAIT #2: nam='PX Deq: Signal ACK' ela= 1 sleeptime/senderid=0 passes=1
p3=0 obj#=-1 tim=3085036618
WAIT #2: nam='PX Deq: Signal ACK' ela= 150 sleeptime/senderid=10
passes=2 p3=0 obj#=-1 tim=3085036789
WAIT #2: nam='PX Deq: Signal ACK' ela= 2 sleeptime/senderid=0 passes=1
p3=0 obj#=-1 tim=3085036858
WAIT #2: nam='PX Deq: Signal ACK' ela= 1 sleeptime/senderid=0 passes=1
p3=0 obj#=-1 tim=3085036888
WAIT #2: nam='PX Deq: Signal ACK' ela= 1 sleeptime/senderid=0 passes=1
p3=0 obj#=-1 tim=3085036911
... output snipped ...
WAIT #2: nam='PX Deq: Signal ACK' ela= 3 sleeptime/senderid=200
passes=1 p3=0 obj#=-1 tim=3085058066
WAIT #2: nam='PX Deq: Signal ACK' ela= 85 sleeptime/senderid=200
passes=2 p3=0 obj#=-1 tim=3085058191
WAIT #2: nam='PX Deq: Signal ACK' ela= 3 sleeptime/senderid=200
passes=1 p3=0 obj#=-1 tim=3085058272
WAIT #2: nam='PX Deq: Signal ACK' ela= 4 sleeptime/senderid=200
passes=1 p3=0 obj#=-1 tim=3085058328
WAIT #2: nam='PX Deq: Signal ACK' ela= 2 sleeptime/senderid=200
passes=2 p3=0 obj#=-1 tim=3085058373
WAIT #2: nam='PX Deq: Signal ACK' ela= 1 sleeptime/senderid=200
passes=1 p3=0 obj#=-1 tim=3085058423
WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1111838976
#bytes=1 p3=0 obj#=-1 tim=3085058657
*** 2010-02-02 13:51:05.499
WAIT #2: nam='SQL*Net message from client' ela= 14120193 driver
id=1111838976 #bytes=1 p3=0 obj#=-1 tim=3099178884 <---- 2nd wait
(14.12 sec)
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='PX COORDINATOR (cr=12 pr=0
pw=0 time=19882318 us)'
STAT #2 id=2 cnt=0 pid=1 pos=1 obj=0 op='PX SEND QC (ORDER) :TQ10015
(cr=0 pr=0 pw=0 time=0 us)'
STAT #2 id=3 cnt=0 pid=2 pos=1 obj=0 op='SORT ORDER BY (cr=0 pr=0 pw=0
time=0 us)'
STAT #2 id=4 cnt=0 pid=3 pos=1 obj=0 op='PX RECEIVE (cr=0 pr=0 pw=0 time=0 us)'
STAT #2 id=5 cnt=0 pid=4 pos=1 obj=0 op='PX SEND RANGE :TQ10014 (cr=0
pr=0 pw=0 time=0 us)'
... output snipped ...
- Karl Arao
karlarao.wordpress.com
--
//www.freelists.org/webpage/oracle-l
Other related posts: