Personal tools
You are here: Home Volume I - Issue 2 "SQL*Net message to client" isn't what you might think it is
Document Actions

"SQL*Net message to client" isn't what you might think it is

by Cary Millsap

Here's a fun fact about the 'SQL*Net message to client' timed event.

Look at the strace data I've included below. This is from a 10.1.0.3.0 database running on Red Hat.

Notice that the trace line saying that the 'SQL*Net message to client' timed event “took” 48 microseconds actually printed to the trace file ([LINE 1]) before the event actually occurred ([LINE 2]). How can Oracle know how long an event has taken when that event hasn’t occurred yet?

The actual time taken to write data from the Oracle side of the pipe to the "client" side of the pipe is tallied in the 'SQL*Net message from client' event ([LINE 3]).

It’s a bug. It's been around forever (v6 or prior, as far as I know). Oracle knows about it. There may be a fix in version 11.

The bug doesn't matter much for performance diagnosis. The count of 'SQL*Net message to client' events is correct. And the performance problems you find with '... to/from client' timed events don’t often require you to know whether the problem is on the inbound or outbound communication. Usually the problem is that there’s any communication going on there in the first place.

But it does sometimes help to know what I'm saying here when a Method R skeptic wants to know why the 'SQL*Net message to client' time doesn't increase when the amount of data returned by a query increases.

write(5, "\n", 1)                       = 1
times(NULL)                             = 53663644
gettimeofday({1105481879, 577241}, NULL) = 0
gettimeofday({1105481879, 577302}, NULL) = 0
getrusage(RUSAGE_SELF, {ru_utime={1, 410000}, ru_stime={5, 30000}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={1, 410000}, ru_stime={5, 30000}, ...}) = 0
times(NULL)                             = 53663644
gettimeofday({1105481879, 577549}, NULL) = 0
gettimeofday({1105481879, 577598}, NULL) = 0
times(NULL)                             = 53663644
[LINE 1] write(5, "WAIT #9: nam=\'SQL*Net message to client\' ela= 48 p1=1650815232 p2=1 p3=0", 72) = 72
write(5, "\n", 1)                       = 1
times(NULL)                             = 53663644
gettimeofday({1105481879, 577887}, NULL) = 0
[LINE 2] write(10, "\0\204\0\0\6\0\0\0\0\0\4\1\0\0\0\34\0\1\1\0\0\0{\5\0\0\0\0\t\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\36\0\0\1\0\0\0006\1\0\0\0\0\0\0\300\257\375\v\0\0\0\0\0\0\0\0\0\0\0\0"..., 132) = 132
read(7, "\0\300\0\0\6\0\0\0\0\0\21i\37@3\364\10\1\0\0\0\t\0\0\0\3^ !\200\0\0\0\0\0\0\214W\364\10\37\0\0\0\354t\362\10\r\0\0\0\0\0\0\0 u\362\10\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2064) = 192
gettimeofday({1105483109, 742217}, NULL) = 0
times(NULL)                             = 53786660
times(NULL)                             = 53786660
gettimeofday({1105483109, 742370}, NULL) = 0
times(NULL)                             = 53786660
write(5, "*** 2005-01-11 16:38:29.742", 27) = 27
write(5, "\n", 1)                       = 1
times(NULL)                             = 53786660
[LINE 3] write(5, "WAIT #9: nam=\'SQL*Net message from client\' ela= 1201332353 p1=1650815232 p2=1 p3=0", 82) = 82
write(5, "\n", 1)                       = 1



Powered by Plone, the Open Source Content Management System

This site conforms to the following standards: