SQL*Net message from client

A client asked about why it takes 14.96 seconds for below sql(1):

SQL>select * from dba_tables;
Elapsed: 00:00:14.96

While it takes only 0.59 second for this sql(2):

SQL>select count(*) from dba_tables;
Elapsed: 00:00:00.59

Let’s compare the tkprof summary from sql tracing for those two sqls:

SQL ID: 105pqbbz8a011 Plan Hash: 1710722978

select *
from
dba_tables

call    count  cpu    elapsed    disk  query     current    rows
------- ------ ------ ---------- ----- --------- -------- -------
Parse      1   0.00   0.00       0           0        0        0
Execute    1   0.00   0.00       0           0        0        0
Fetch   3427   2.87   2.88       0       38588        0    51377
------- ------ ------ -------- ---------------- ---------- -------
total   3429   2.87   2.88       0       38588        0     51377

Elapsed times include waiting on following events:
  Event waited on                  Times  Max. Wait Total Waited
  -----------------------------   Waited  ---------  -----------
  SQL*Net message to client         3427       0.00         0.00
  Disk file operations I/O             1       0.00         0.00
  gc current block 2-way               2       0.00         0.00
  gc current block 3-way               1       0.00         0.00
  gc cr block 2-way                    6       0.00         0.00
  gc cr block 3-way                    2       0.00         0.00
  SQL*Net message from client       3427       0.26        11.75
******************************************************************

SQL ID: 56bs32ukywdsq Plan Hash: 1650942002

select count(*)
from
dba_tables


call    count   cpu  elapsed  disk  query current    rows
------- ------ ----- -------- ----- ----- ---------- ------
Parse      1    0.00    0.00     0      0    0         0
Execute    1    0.00    0.00     0      0    0         0
Fetch      2    0.57    0.58     0  33542    0         1
------- ------ ----- --------- ----- ------ ------- -------
total      4    0.57    0.58     0  33542    0         1

Elapsed times include waiting on following events:
  Event waited on               Times   Max. Wait Total Waited
  ----------------------------  Waited  --------  -----------
  SQL*Net message to client         2      0.00          0.00
  gc current block 2-way            2      0.00          0.00
  gc current block 3-way            1      0.00          0.00
  gc cr block 3-way                 1      0.00          0.00
  gc cr block 2-way                 4      0.00          0.00
  SQL*Net message from client       2      0.00          0.00
***************************************************************

We can see sql(1) takes 2.88 seconds for 3427 fetches, compared to 0.58 second for  sql(2)’s  2 fetches only.

The big difference is for ” SQL*Net message from client” wait event. For sql(1), all records need to be fetched and sent to the client terminal , and then displayed. For sql(2), only an integer number of total records needs to be sent to the client terminal , and then displayed.

So “SQL*Net message from client” wait event starts immediately after every fetch, until all the fetched data are sent to client terminal and displayed.

The below popular saying for ” SQL*Net message from client”  is NOT accurate:

"SQL*Net message from client" means Oracle is just waiting on some
work to do. It means that you have a session connected and Oracle
is waiting for a command so it can do something.

Actually “SQL*Net message from client” wait event occurs between fetches in the same sql with many fetches, not necessarily database server is waiting for new sql command from client. Here is the extracted trace file from sql(1) to show this wait event:

...
..

FETCH #139988924732624:c=807,e=807,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1710722978,tim=1547182112856786
WAIT #139988924732624: nam='SQL*Net message from client' ela= 2632 driver id=1650815232 #bytes=1 p3=0 obj#=18 tim=1547182112859472
WAIT #139988924732624: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=18 tim=1547182112859608

FETCH #139988924732624:c=755,e=755,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1710722978,tim=1547182112860284
WAIT #139988924732624: nam='SQL*Net message from client' ela= 3254 driver id=1650815232 #bytes=1 p3=0 obj#=18 tim=1547182112863584
WAIT #139988924732624: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=18 tim=1547182112863703

FETCH #139988924732624:c=746,e=746,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1710722978,tim=1547182112864385
WAIT #139988924732624: nam='SQL*Net message from client' ela= 3214 driver id=1650815232 #bytes=1 p3=0 obj#=18 tim=1547182112867646
WAIT #139988924732624: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=18 tim=1547182112867776

FETCH #139988924732624:c=887,e=887,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1710722978,tim=1547182112868591
WAIT #139988924732624: nam='SQL*Net message from client' ela= 3152 driver id=1650815232 #bytes=1 p3=0 obj#=18 tim=1547182112871811
WAIT #139988924732624: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=18 tim=1547182112871943

FETCH #139988924732624:c=2465,e=2517,p=0,cr=42,cu=0,mis=0,r=15,dep=0,og=1,plh=1710722978,tim=1547182112874386
WAIT #139988924732624: nam='SQL*Net message from client' ela= 3291 driver id=1650815232 #bytes=1 p3=0 obj#=18 tim=1547182112877761
WAIT #139988924732624: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=18 tim=1547182112877912
...
..
.

For a sql,  total “SQL*Net message from client” wait event time = Fetches * latency +Data display time on terminal + Waiting time  for new command from client.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google photo

You are commenting using your Google account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s

This site uses Akismet to reduce spam. Learn how your comment data is processed.