Re: Strange wait for what should be a fast query

  • From: "Charles Schultz" <sacrophyte@xxxxxxxxx>
  • To: "Cary Millsap" <cary.millsap@xxxxxxxxxx>
  • Date: Tue, 19 Dec 2006 15:54:05 -0600

Thanks, Cary.

This is a java app, but your response does give me food for thought. The
trace file is not very helpful while looking for "XCTEND" - does not come
until much later at timestamp 7926653175799.

So I am thinking to myself (out loud), "Is there anything in Java that would
exhibit the same kind of behavior that Cary described?"

On 12/19/06, Cary Millsap <cary.millsap@xxxxxxxxxx> wrote:

 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

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.

*Nullius in verba*

Hotsos Symposium 2007 / March 4–8 / Dallas

Visit 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
*Subject:* Strange wait for what should be a fast query

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

select user

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  ----------
  SQL*Net message to client                       4        0.00
  SQL*Net message from client                     4     1843.75

 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
PARSE #3:c=0,e=45,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=2,tim=7923152389704
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

Charles Schultz

Other related posts: