SQL*Net message from client

Posted on by
I have been working a lot with a Siebel system in the US. While analyzing performance problems, I noticed that we spent a lot of time in SQL*Net message from client. As you surely know this is an idle event, as such you might think it can be ignored. Well it depends, I have read one blog by Kyle Hailey and one white paper by Hotsos which I think explain the event very good.

Back to my 10046 tracefile, this is what I saw..
Elapsed times include waiting on following events:
 Event waited on                          Times  Max.Wait   Total 
                                          Waited            Waited
 --------------------------------------------------------------
 SQL*Net message to client              346       0.00         0.00
 db file scattered read                  68       0.00         0.00
 SQL*Net message from client            346      42.78        44.59
 db file sequential read                  2       0.00         0.00
*******************************************************************
So we can see I spent in total 44.59 seconds in SQL*Net message from client, what i found worrying was that max wait was 42.78 seconds. This means one of my 346 waits took 42.78 seconds, that is a majority of the time. So when I looked into the raw 10046 trace file I noticed that it is always the last SQL*Net message from client for that cursor that was responsible for that time, just prior to the close cursor or sometimes where the next cursor started.
WAIT #140276043879256: nam='SQL*Net message from client' ela= 35132 driver id=1650815232 #bytes=1 p3=0 obj#=114244 tim=1399300904474816
WAIT #140276043879256: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=114244 tim=1399300904474890
FETCH #140276043879256:c=0,e=173,p=0,cr=7,cu=0,mis=0,r=15,dep=0,og=1,plh=3617692013,tim=1399300904475046
WAIT #140276043879256: nam='SQL*Net message from client' ela= 3186 driver id=1650815232 #bytes=1 p3=0 obj#=114244 tim=1399300904478283
WAIT #140276043879256: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=114244 tim=1399300904478351
WAIT #140276043879256: nam='db file scattered read' ela= 99 file#=4 block#=1773 blocks=16 obj#=114244 tim=1399300904479181
WAIT #140276043879256: nam='db file scattered read' ela= 20 file#=4 block#=1794 blocks=3 obj#=114244 tim=1399300904479726
WAIT #140276043879256: nam='db file scattered read' ela= 197 file#=4 block#=1805 blocks=48 obj#=114244 tim=1399300904480580
WAIT #140276043879256: nam='db file scattered read' ela= 21 file#=4 block#=1854 blocks=3 obj#=114244 tim=1399300904481718
FETCH #140276043879256:c=3000,e=3493,p=70,cr=121,cu=0,mis=0,r=13,dep=0,og=1,plh=3617692013,tim=1399300904481829
STAT #140276043879256 id=1 cnt=5174 pid=0 pos=1 obj=114244 op='TABLE ACCESS FULL T1 (cr=1538 pr=884 pw=0 time=18708 us cost=333 size=639837 card=3091)'

*** 2014-05-05 16:42:27.268
WAIT #140276043879256: nam='SQL*Net message from client' ela= 42786017 driver id=1650815232 #bytes=1 p3=0 obj#=114244 tim=1399300947267969
CLOSE #140276043879256:c=0,e=13,dep=0,type=0,tim=1399300947268132
Elapsed time is in micro seconds (1/1000000)
So is this hurting my performance or not ? I recommend you to stop here and read the blog and the paper (start with the blog if you don’t want to spend the time to download the paper)
Welcome back! So the question here is this event seen in the cursor “inside” or “outside” the cursor ? As Kyle state it:
“The first two “SQL*Net message from client’ are in the middle of cursor processing and are considered non-idle waits.
The third “SQL*Net message from client” is between cursors and considered an idle event, ie we are waiting for the next command from the client.”
As I see it in my case since it is just prior to the close it is outside the cursor and it can be ignored. By reading the blog/paper I think you also have some good ideas how to handle the other scenarios that might occur.

Leave a comment