RE: Strange wait for what should be a fast query

From: Cary Millsap <cary.millsap_at_hotsos.com>
Date: Tue, 19 Dec 2006 15:34:10 -0600
Message-ID: <C970F08BBE1E164AA8063E01502A71CF86EC2A@WIN02.hotsos.com>

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_at_freelists.org
[mailto:oracle-l-bounce_at_freelists.org] 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 


--
http://www.freelists.org/webpage/oracle-l

Received on Tue Dec 19 2006 - 15:34:10 CST