Skip to Main Content

Breadcrumb

Question and Answer

Tom Kyte

Thanks for the question.

Asked: July 19, 2007 - 4:59 pm UTC

Last updated: September 10, 2012 - 7:21 pm UTC

Version: 10gR2

Viewed 10K+ times! This question is

You Asked

Tom, I have a query that is taking about 20 seconds to execute. But the trace shows me that is executing in about 8 seconds. The problem is in the SQL*Net event? Any suggestion?

Thanks Tom!

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.01       0.01          0          0          0           0
Execute      3      0.00       0.00          0          0          0           2
Fetch       56      8.24       8.09          0        947          0         823
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       62      8.26       8.10          0        947          0         825

Misses in library cache during parse: 1

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                      59        0.00          0.00
  SQL*Net message from client                    58       11.65         22.16

and Tom said...

say the client is:

open cursor
loop
   fetch a row
   take 5 seconds to process row
end loop
close cursor



and further, suppose you have 100 rows to process.. You will have 5 seconds * 100 times the server waited on the client to send it a message (sqlnet message from client)

client is not processing data fast enough.

So in your case, we spent 8 seconds in the server and the client spent 12 seconds not in the server processing the data.


sqlnet message from client is typically not an indication of the database having a problem, but rather the client application not asking us to do anything!

Rating

  (11 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

But when the "SQL *Net message from client" ...

Lasse Jenssen, February 19, 2009 - 9:01 am UTC

... wait is found (in an 10046 trace) connected to one single SELECT statement, how can oracle be waiting for the client? It has just been tolded what to do (the SELECT).

Here is a dump from a 10046 trace using tdvxstat (instead of tkprof):
Text:  SELECT COUNT(*) FROM KONTO WHERE KONTONR = :1 

Execution Plan
Optimizer Mode  CHOOSE 
Rows  Operation 
 
1  SORT AGGREGATE  
1     INDEX UNIQUE SCAN KONTO_IDX (object id 65701) 

Database Call Statistics with Recursive Statements 
Call  Count  Misses  CPU [s]  Elapsed [s]  PIO [b]  LIO [b]  Consistent [b]  Current [b]  Rows 
 
Parse  118  5  0.000  0.028  0  9  9  0  0 
Execute  118  0  0.000  0.035  0  0  0  0  0 
Fetch  118  0  0.000  0.013  0  354  354  0  118 
 
Total  354  5  0.000  0.076  0  363  363  0  118 
 
Average (per execution)  3  0  0.000  0.001  0  3  3  0  1 
 
Average (per row)  3  0  0.000  0.001  0  3  3  0  1 

Database Call Statistics without Recursive Statements
Call  Count  Misses  CPU [s]  Elapsed [s]  PIO [b]  LIO [b]  Consistent [b]  Current [b]  Rows 
 
Parse  118  5  0.000  0.022  0  0  0  0  0 
Execute  118  0  0.000  0.035  0  0  0  0  0 
Fetch  118  0  0.000  0.013  0  354  354  0  118 
 
Total  354  5  0.000  0.070  0  354  354  0  118 
 
Average (per execution)  3  0  0.000  0.001  0  3  3  0  1 
 
Average (per row)  3  0  0.000  0.001  0  3  3  0  1 

Resource Usage Profile  overall current 
Component  Total Duration [s]  %  Number of Events  Duration per Event [s] 
 
SQL*Net message from client  9,112.105  100.000  472  19.305 
recursive statements  0.003  0.000  n/a   n/a  
SQL*Net message to client  0.001  0.000  472  0.000 
CPU  0.000  0.000  n/a   n/a  
 
Total  9,112.110  100.000


I understand the fact that "SQL*NET message from client" found in the database is an idle event, waiting for something to do. But I can't see how this can be an idle event when tied to an SELECT statement (when it's actually told to do something).

Tom Kyte
February 19, 2009 - 1:20 pm UTC

No clue what "tdvxstat" is, why would you use something so non-standard? Use the standard stuff so it is known what we are looking at.



wait events are recorded when something is happening on the server.

So, if you log into the server
and you start something
and you sit there (you are accumulating "message from client" wait time)
and then you finish something - that wait event is associated with "something"


ops$tkyte%ORA10GR2> variable x refcursor
ops$tkyte%ORA10GR2> set serveroutput off
ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> @trace
ops$tkyte%ORA10GR2> alter session set events '10046 trace name context forever, level 12';

Session altered.

ops$tkyte%ORA10GR2> !date
Thu Feb 19 18:12:18 PST 2009

ops$tkyte%ORA10GR2> exec open :x for select * from dual;

PL/SQL procedure successfully completed.

ops$tkyte%ORA10GR2> pause

ops$tkyte%ORA10GR2> !date
Thu Feb 19 18:12:35 PST 2009

ops$tkyte%ORA10GR2> print x

D
-
X


Ok, so at 18 seconds past 18:12, we opened a cursor.

Then we hung out for 16-17 seconds and then we decided to fetch from the cursor.

tkprof says:

BEGIN open :x for select * from dual; END;


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           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 494

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1       16.52         16.52


the wait time was just associated with something.

This indicates your client opened something - hung out and wasted time, killed time, did whatever - and then asked us to do more work.

whats its waiting on?

A reader, February 19, 2009 - 7:29 pm UTC

Tom,

You have explicit pause and that seen on the trace. But as the questioner asked, he told the sql*plus to execute the statement? Why "SQL*Net message from client" wait?

Sorry, not seeing entire picture. Can you please explain?

Thanks.
Tom Kyte
February 21, 2009 - 8:41 pm UTC

what questioner said they told the sqlplus to execute the statement????

I don't see that at all.

The said "how can the event be associated to a statement", they said "we executed something and later we see it had this wait associated with it" (no mention of sqlplus or anything)

I used sqlplus to show what happened - their client code

a) did something in the database
b) paused - did something non-database related
c) did something else in the database


I answered - the event is associated with SOMETHING, that something is the last thing we were told to do - parse something, fetch something, run something - we were told to DO SOMETHING and then we waited and waited. When were were done waiting - we recorded that fact (that we were done) and that was associated with whatever we were told to do.

So this means ...

Lasse Jenssen, February 23, 2009 - 6:06 pm UTC

... that all wait events in a trace that follows a SELECT statement (for instance), until some other statment is issued, will be related to the first statement.

Lets say I issue a statement A (SELECT * FROM EMP;) in sqlplus (or by some othere client). The statement is procecuted in the server going through parse, execute and fetch. Now the server (or session) has something to do, and will not issue a "SQL*Net message from client" wait (On these stages we'll see other waits as latch free, db file seq reads, db file scattered reads, buffer busy wait etc). After a while statement A is completed (and the user is left
with the result (example 5 rows selected). As the user takes a brake (don't do another command), we will start to see "SQL*NET message from client" waits in the tracefile.
Now it seems to me that all these waits registered after statement A finishes, until the next statement is issued, is tied to statement A in the trace output. Am I understanding this correct? So the wait event is not really tied to the running of statement A, but the time between statement A completed and another statement B started? Is my understanding of this correct?

When it comes to tvdxtat, i use it once in a while (Most of the time I use tkprof). Tvdxtat is a tool made by Christian Antognini, that addresses some problems with tkprof. One of the things tvdxtat do (that tkprof doesn't), is to show all the bind values related to the execution of queries in a tracefile.

Thanks for your answers Tom!
Regards,
Lasse Jenssen
Tom Kyte
February 24, 2009 - 5:50 am UTC

.. Now the server (or session) has something to do, and will
not issue a "SQL*Net message from client" wait ..

no, the sqlnet message from client means the server has done its work, has sent the result to the client and the server is waiting for the client to say 'do something'

... (On these stages we'll see other
waits as latch free, db file seq reads, db file scattered reads, buffer busy
wait etc). ...

no, you won't, we cannot be waiting on a latch on the server side if WE ARE WAITING to be told to do something, only if we are doing something can we be waiting on a latch. If we are in sqlnet message from client wait - we are waiting on the server side for the client to tell us to do something.


Basically

a) client said do X
b) server did X, server tells client "here is the result of X"
c) server is in sqlnet message from client wait........
d) client says do Y


X could be

o parse this sql
o fetch a row
o close that sql
o execute this statement
o etc


it could be anything - but when we are in sqlnet message from client, we are patiently waiting for client to tell us to do something, you wont see other waits intermingled, we are doing NOTHING on the server side, we are waiting for the client and will not be waiting for anything else.



Please just use standard tools - tkprof, statspack, awr - we can get pretty much everything we need from it. Stick with the standards and we'll cut down on (my) confusion trying to figure out what I'm looking.

Thanks ... that was actually what I was trying to say :-)

Lasse Jenssen, February 24, 2009 - 6:48 am UTC 

Hi Tom

Thanks again!
This was actually what i was trying to say (I Thought I exlained it well, but I was obviously wrong). At least your explaination was good enough for me, and a see where i originally got confused (i hope).
 
My confusion and original question was related to how "SQL*Net Message from client" waits are presented in the tkprof output. In these outputs it seems like the wait are related to the actuall processing of the statement it's presented together with. As in this tkprof output:

<code>SELECT KON_NR
FROM
 LJ_KONS


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       26      0.00       0.00          0          0          0           0
Execute     26      0.00       0.00          0          0          0           0
Fetch       26      0.00       0.00          0         78          0          26
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       78      0.00       0.01          0         78          0          26

Misses in library cache during parse: 2
Optimizer goal: CHOOSE
Parsing user id: 189

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS FULL LJ_KONS


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                      78        0.00          0.00
  SQL*Net message from client                    78      135.45        319.65


I had a hard time understanding how this (read: SQL*Net message from client) wait could be related to the actuall processing of the above select statement. If i understand you correct - it doesn't relate. These(read: SQL*Net message from client) waits (and wait time elapsed) are related to the time AFTER the completion of the actual query, where the server is waiting for more to do. Right?</code>
Tom Kyte
February 24, 2009 - 6:53 am UTC

yes, correct, the wait event is attached to "something", the server - when doing "something" never is really waiting on Message from client - it only waits on that in between doing "something"

A little variation in the same event..

Manjunath, August 08, 2009 - 4:24 am UTC

Hi Tom,

I had the following in my case:

Event Time_waited_micro
sql *net message to client 5,658,507
sql *net more data to client 218,648
sql *net message from client 33,183,918,229
sql *net more data from client 3,208,274,662

My Oracle version is 10.2.0.4.

The above waits were occuring while inserting(through direct load) into a table that has around 700 columns and the average row length is around 2500 bytes. Although we have a very small buffer cache(2Gigs is the sga_target), as it is a direct path load, buffer cache is not the issue. I was feeling that we may need to look at the values of SDU/MTU etc. Is my hunch correct that in the above case, 'sql *net message from client' is NOT an idle time but is very much related to the next item: 'sql *net more data from client'? And that it is clearly telling that Oracle is waiting for the next packet of data to arrive?

Thanks and regards
Manjunath
Tom Kyte
August 11, 2009 - 1:05 pm UTC

I would look at this first and say "client takes a long time to create a bundle to send to server"

I would start by first proving that the time is not being spent in the client. Of course your developers have instrumented their code so they can tell you this right?


Sorry for the delayed response..

Manjunath, August 13, 2009 - 2:43 pm UTC

Hi Tom,
No, unfortunately the app is not so instrumented. So, any mapping that is running delayed in our Test environment we start looking at it again and it is usually the DBA's that are entrusted with this.:-)
Things are getting better though, albeit a little slowly.
On this specific issue, I am still trying to work with our onsite team to change the SDU setting. I also learnt now that starting 11g, SDU setting defaults to 8k from 2k until 10g.

Thanks and regards
Manjunath

sqlnet message from client and Parsing

VLS, August 23, 2009 - 10:42 am UTC

Hi Tom,

As per the TKPROF output posted by Lasse Jenssen on February 24th, 2009, a simple query is doing 78 Logical I/O's to fetch 26 rows. The alarming issue, in this example is, the number of Parse and Executions. These 26 each with 2 Misses in the Library cache. I have few questions, for my clarification and understanding :

1. From the TKPROF posted by Lasse, does it mean, that 24 out of 26 parses are soft parses ?

2. In one of your original question

http://asktom.oracle.com/pls/asktom/f?p=100:11:0::::P11_QUESTION_ID:1860804200346441327

you mentioned something on heave parsing. Cary Millsap, in one of his book, also wrote about the possibility of SQL*Net message from client waits due to parsing. Therefore, for the tkprof posted by Lasse, can we attribute this wait to be because of Parsing ?

3. I need to know the reason for the waits on SQL*Net due to parsing ?

Would appreciate your update.

Thanks in advance.

Regards
VLS
Tom Kyte
August 25, 2009 - 9:32 am UTC

just for reference:

SELECT KON_NR
FROM
 LJ_KONS


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       26      0.00       0.00          0          0          0           0
Execute     26      0.00       0.00          0          0          0           0
Fetch       26      0.00       0.00          0         78          0          26
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       78      0.00       0.01          0         78          0          26

Misses in library cache during parse: 2


... 1. From the TKPROF posted by Lasse, does it mean, that 24 out of 26 parses are
soft parses ?
....

yes. they are bad soft parses. they should not be done, there should have been 1 parse only.

... Therefore, for the tkprof posted by Lasse, can we attribute this wait
to be because of Parsing ? ...

no, you have taken a statement from Cary's book out of context and ask us to generalize with it, no, you cannot make that statement, we cannot attribute that wait to parsing.


3) there is not necessarily a connection between the two.

consider:

ops$tkyte%ORA10GR2> alter session set events '10046 trace name context forever, level 12';

Session altered.

ops$tkyte%ORA10GR2> select systimestamp from dual d1;

SYSTIMESTAMP
---------------------------------------------------------------------------
25-AUG-09 09.03.07.960925 AM -04:00

ops$tkyte%ORA10GR2> pause

ops$tkyte%ORA10GR2> select systimestamp from dual d2;

SYSTIMESTAMP
---------------------------------------------------------------------------
25-AUG-09 09.03.12.090191 AM -04:00

ops$tkyte%ORA10GR2> pause

ops$tkyte%ORA10GR2> select systimestamp from dual d3;

SYSTIMESTAMP
---------------------------------------------------------------------------
25-AUG-09 09.03.18.423713 AM -04:00

ops$tkyte%ORA10GR2> pause

ops$tkyte%ORA10GR2> disconnect



select systimestamp from dual d1

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.00       0.00          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          0          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
  SQL*Net message from client                     2        4.02          4.03

<b>i waited 4 seconds between d1 and d2... you can see the timestamps</b>
********************************************************************************
select systimestamp from dual d2

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.00       0.00          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          0          0           1

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       3        0.00          0.00
  SQL*Net message from client                     3        6.17          6.19

<b>I waited 6+ seconds between d2 and d3, I got my coffee mug this time...</b>
********************************************************************************
select systimestamp from dual d3

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.00       0.00          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          0          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
  SQL*Net message from client                     2        3.93          3.95


It is predominantly time spent in the client, not in the database

Total session time

Flavio, April 08, 2010 - 3:10 pm UTC

Hi,

From the TKprof below I see:
- that the server took about 23 minutes waiting for the client and that the other waiting events were irrelevant.
- that the server took almost 2 minutes executing something (69.71s + 40.49s).

But my session took 2 hours to complete. Where did the 1h35m go? What am I missing here?


OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 66829 1.92 1.93 0 0 0 0
Execute 66829 56.20 62.96 1111 89349 488698 56437
Fetch 10392 0.43 4.81 703 31596 0 10103
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 144050 58.56 69.71 1814 120945 488698 66540

Misses in library cache during parse: 467
Misses in library cache during execute: 7

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 133901 0.00 0.13
SQL*Net message from client 133901 0.41 1364.60
db file sequential read 706 0.08 4.44
SQL*Net more data to client 1890 0.00 0.02
log file sync 489 0.10 0.36
latch: shared pool 1 0.00 0.00
latch: library cache 2 0.00 0.00
latch free 1 0.01 0.01


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 21572 0.18 0.25 0 0 20 0
Execute 99368 28.85 35.54 1108 87644 467167 85881
Fetch 22167 4.45 4.69 4 1545 21523 22060
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 143107 33.50 40.49 1112 89189 488710 107941

Misses in library cache during parse: 20
Misses in library cache during execute: 20

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 1105 0.21 6.94
latch: library cache 1 0.00 0.00
log file switch completion 1 0.05 0.05

Thank you very much.

Tom Kyte
April 13, 2010 - 8:28 am UTC

not 100% of everything is in the trace (unfortunately).

in the raw trace, there is a tim= field at the end of many records, if you are digging - you might generate something that looks for large "gaps" - missing time, time you cannot account for and look to see what was happening in the trace right before that. That would give us a clue to see what was happening.

SQL*Net message from client

Lasse Jenssen, June 14, 2010 - 6:13 am UTC

Hi Tom
I spent this weekend in a taskforce regarding some batch jobs. The batch application is a thick client written i VB, running on a windows boxs. The database is running in the same nettwork on an AIX boks. This is a relative new system, and the big change is the increase in customers, and transaction to be processed.

The client and database used to be separated by multiple firewalls, this is now redesigned, but the change did not generate the expected result. The response times were reduced to 1/4 of the original, but are still way too high.

This weekend I did some traces of some batch processes, and the output tolded me that the application was doing single statement processing. Probably one or more loops with a log of single statements.

The example below is from a batch that ran for 27 min (1620 seconds). This timing was done from the client side.

From the database trace we see the following:
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse     9001      0.08       0.60          4        670          0           0
Execute 208395     12.15     218.88       9091     594271     535394       80847
Fetch   120998      1.68      46.25       3159    1943377          0      107110
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   338394     13.91     265.74      12254    2538318     535394      187957

Misses in library cache during parse: 105
Misses in library cache during execute: 32

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                  347863        0.03          0.29
  SQL*Net message from client                347863      170.94       1566.72
  log file sync                                8926        0.40         28.19
  db file sequential read                     12214        0.25        112.58
  db file scattered read                         16        0.13          0.20
  SQL*Net more data from client                   2        0.00          0.00
  SQL*Net more data to client                  2236        0.00          0.05
  SQL*Net break/reset to client                  13        0.00          0.00
  latch free                                      3        0.00          0.00
  log file switch completion                      2        0.24          0.46


The database seems to be related to 250 sec (15 %) of the response time. The rest is waiting for the application. If we look at one of the statements generating the "SQL*Net message from client" waits, we see the following:

********************************************************************************

SELECT * 
FROM
 XXXXX WHERE INST_NUMBER = :B01 AND ART_NUMBER = 
  :B02 AND TYPE = :B03 AND START_DATE =      (SELECT 
  MAX(START_DATE) FROM XXXXX      WHERE 
  INST_NUMBER = :B04   AND ART_NUMBER = :B05 AND TYPE = 
  :B06      AND START_DATE <= :B07      AND START_DATE >= :B08)
   

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute  21120      1.14      30.88       1980     284199          0           0
Fetch    21120      0.08       7.92        755      79897          0       19974
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    42242      1.22      38.80       2735     364096          0       19974

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 63  

Rows     Row Source Operation
-------  ---------------------------------------------------
  19974  PARTITION RANGE SINGLE PARTITION: KEY KEY (cr=364096 pr=2735 pw=0 time=29227161 us)
  19974   TABLE ACCESS BY LOCAL INDEX ROWID XXXXX PARTITION: KEY KEY (cr=79897 pr=755 pw=0 time=7340547 us)
  19974    INDEX UNIQUE SCAN IX_XXXXX PARTITION: KEY KEY (cr=59922 pr=0 pw=0 time=233216 us)(object id 66224)
  21120     SORT AGGREGATE (cr=284199 pr=1980 pw=0 time=21689133 us)
  19974      FILTER  (cr=284199 pr=1980 pw=0 time=21484719 us)
  19974       PARTITION RANGE ITERATOR PARTITION: KEY KEY (cr=284199 pr=1980 pw=0 time=21426778 us)
  19974        FIRST ROW  (cr=284199 pr=1980 pw=0 time=21011886 us)
  19974         INDEX RANGE SCAN (MIN/MAX) IX_XXXXX PARTITION: KEY KEY (cr=284199 pr=1980 pw=0 time=20820782 us)(object id 66224)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                   42247        0.00          0.03
  SQL*Net message from client                 42247        0.14        159.62
  db file sequential read                      2735        0.25         26.02
********************************************************************************


The average wait on the client is (160 sec/21120) 0,0018 sec per execution.

This looks like one of the settings where "SQL*Net message from client" do matters. And that the findings above points towards bad design. This design do not (and never will) scale. I've launched this theory in the taskforce, but the third-party resources responsible for the application do not agree (strangly enough :-)). I've not launched this as a final conclusion, but as a theory. Do you agree that the numbers above points towards application design?
Tom Kyte
June 22, 2010 - 8:22 am UTC

.. .This looks like one of the settings where "SQL*Net message from client" do matters. ...

who said anywhere that it doesn't matter? I've written many many many times that this points to a bottleneck in the *client*, not the server. It is not indicative of a database problem but a client problem. Making the database "more tuned" will not solve anything here - you have to look to the poor client implementation.

As soon as you wrote:

The batch application is a thick client written i VB, running on a windows boxs.

I knew immediately where the problem would be, I didn't really need to read the rest.

If the 3rd party disagrees, what is THEIR hypothesis. Since only 15% of the time is recorded in the database - where do THEY feel the other 85% of the time is???


It is in their application - it is the time we spent AFTER executing the above select (for example) and waiting for their next command.


Tell them to write a small program in VB such as:

connect
dbms_monitor.session_trace_enable( waits => true );
select * from dual before;

for i in 1 .. 50000
loop
   select * from dual;
   sleep(1);
end loop

select * from dual after;
exit


trace that, and then run it again with the sleep(1) commented out. Then review that result. It will look a lot like what you are already looking at (the first run will). The second run will look like what you could have if you did the processing IN THE CLIENT faster.

Vishnu, September 04, 2012 - 5:46 am UTC

Hi Tom & team I also observed simillar issue in one of the report. In the begining this report takes arounf 2 - 3 min to complete but now talking 48 hrs and its true. We have tested by creating index for few tables but no big improvement in performance. The TKPROF details are as below -
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 301 0.00 0.00
SQL*Net message from client 301 1088.89 3415.18
db file sequential read 7924 0.61 56.28
SQL*Net more data to client 5 0.00 0.00
db file scattered read 236 0.09 4.07
log file sync 8 0.00 0.00
SQL*Net more data from client 1 0.00 0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 349 0.05 0.07 0 0 0 0
Execute 755 0.34 0.54 24 31 81 12
Fetch 2130 0.22 4.42 487 3578 0 1780
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3234 0.61 5.04 511 3609 81 1792

&

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 498 0.05 4.43
Disk file operations I/O 2 0.00 0.00
db file scattered read 2 0.01 0.02

99 user SQL statements in session.
235 internal SQL statements in session.
334 SQL statements in session.
10 statements EXPLAINed in this session.

Tom Kyte
September 10, 2012 - 7:21 pm UTC

SQL*Net message from client 301 1088.89 3415.18


we were waiting for the client to tell us to do something, your program was eating all of the time, we (the database) did hardly anything.

do you see the time spent in the database? almost NOTHING.

SQL*Net message from client

A reader, December 24, 2014 - 3:39 am UTC

Hi Tom,

Similar to above postings, I have scenario where batch is run in multithreaded fashion and in trace file we get to see below

SELECT 1
FROM
DUAL


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 23 0.00 0.00 0 0 0 0
Fetch 23 0.00 0.00 0 0 0 23
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 46 0.00 0.00 0 0 0 23

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS


Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
0 FAST DUAL


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 23 0.00 0.00
SQL*Net message from client 23 120.01 2664.98

Why a query on dual have huge number of "SQL*Net message from client" wait events and how to analyze this issue.
And it also shows 23 rows returned

Regards,
Girish
more

Connor and Chris don't just spend all day on AskTOM. You can also catch regular content via Connor's blog and Chris's blog. Or if video is more your thing, check out Connor's channel and Chris's channel from their Youtube channels. And of course, keep up to date with AskTOM via the official twitter account.