Home -> Mailing Lists -> Oracle-L -> Re: orasrp SQL*Net message to client as non-idle event

Re: orasrp SQL*Net message to client as non-idle event

From: Karl Arao <karlarao_at_gmail.com>
Date: Mon, 8 Feb 2010 08:30:00 +0800
Message-ID: <12ee65601002071630r71bc9df7i54b90f1c91148dd2_at_mail.gmail.com> 





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 ...










Received on Sun Feb 07 2010 - 18:30:00 CST












Original text of this message