Re: Strange wait for what should be a fast query

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_at_hotsos.com> 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
> 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
>

-- 
Charles Schultz

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