RE: Strange wait for what should be a fast query

A common real-life scenario that would create exactly this trace file
is:

 

12:00:00n Execute "sqlplus"

12:01:00.00p Execute "select user from dual;" within sqlplus.

12:01:00.01p View the output from your sqlplus query.

12:01:01p Take a phone call, go to the bathroom, wander the halls for a
bit.

12:30p (approximately) Execute "exit" within sqlplus.

12:31p Look at your trace file, which reveals that your Oracle kernel
process spent about a half hour of time spent blocking on a read from
the I/O device to which your SQL*Net code stack is attached, listening
for the instruction to follow the FETCH call from the "select" cursor
you opened. ...Which, ultimately, was "exit", which, in turn, causes
sqlplus to issue a "commit" database call and disconnect.

 

If you did this from sqlplus, then I'd expect the next line in the trace
data to be "XCTEND...".

 

 

Cary Millsap

Hotsos Enterprises, Ltd.

http://www.hotsos.com

Nullius in verba

 

Hotsos Symposium 2007 / March 4-8 / Dallas

Visit www.hotsos.com for curriculum and schedule details...

________________________________

From: oracle-l-bounce@xxxxxxxxxxxxx
[mailto:oracle-l-bounce@xxxxxxxxxxxxx] On Behalf Of Charles Schultz
Sent: Tuesday, December 19, 2006 3:04 PM
To: ORACLE-L
Subject: Strange wait for what should be a fast query

 

We have an application that is consistently seeing this so-called "idle"
wait:

select user 
from
 dual

 

call     count       cpu    elapsed       disk      query    current
rows
------- ------  -------- ---------- ---------- ---------- ----------
----------
Parse        4      0.02       0.01          0          0          0
0
Execute      4      0.00       0.00          0          0          0
0
Fetch        4      0.00       0.00          0          0          0
4
------- ------  -------- ---------- ---------- ---------- ----------
----------
total       12      0.02       0.01          0          0          0
4

 

Misses in library cache during parse: 1
Optimizer mode: FIRST_ROWS
Parsing user id: 13992  

 

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  FAST DUAL  (cr=0 pr=0 pw=0 time=13 us)

 

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



I am very perplexed about this - what possible message is SQL*Net
waiting for from the client?

Here is the corresponding info from the raw trace file (from the 4th and
final fetch): 

select user from dual
END OF STMT
PARSE #3:c=0,e=45,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=2,tim=7923152389704
BINDS #3:
EXEC #3:c=0,e=115,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=2,tim=7923152389991
WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1413697536
#bytes=1 p3=0 obj#=58 tim=7923152390127
FETCH #3:c=0,e=42,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=2,tim=7923152390255
*** 2006-12-19 09:10:27.832
WAIT #3: nam='SQL*Net message from client' ela= 1843756325 driver
id=1413697536 #bytes=1 p3=0 obj#=58 tim=7926058417512



-- 
Charles Schultz

Other related posts: