Re: v$wait_event: wait

From: Charles Hooper <hooperc2000_at_yahoo.com>
Date: Thu, 14 Jun 2007 08:08:04 -0700
Message-ID: <1181833684.752390.12760@o11g2000prd.googlegroups.com>

On Jun 14, 10:06 am, Chuck <skilover_nos..._at_bluebottle.com> wrote:
> I know this question was asked before but I don't think the answer was
> clear. I have the following returned from a query of v$session_wait
>
> SID EVENT WAIT_TIME SECONDS_IN_WAIT STATE
> --- -------------- --------- --------------- -----------------
> 19 latch free -1 361 WAITED KNOWN TIME
>
> The seconds_in_wait is constantly increasing. According to the 9i docs,
> the wait_time of -1 and state indicate that the wait event was very
> short and is now over. But if I look at the server process for sid 19,
> it's eating up cpu like there's no tomorrow (12.4% on an 8 cpu server).
> What exactly is the server process doing? Normally you can tell by the
> wait events but apparently not in this case.
>
> This process sat on the "latch free" event for 20 minutes with the
> seconds_in_wait increasing. If I run it again it may show up as sitting
> on "scattered read" for 20 minutes before finishing. A third time it may
> sit on "sql*net message from client" all the while the server process is
> running away with cpu. What is going on
>
> DB Version is 9.2.0.5. O/S is solaris.
>
> TIA
In Oracle 10.2.0.2, I have found that the wait events do not always provide enough detail, in some cases 80% of the execution time is unaccounted for by the wait events (the missing time can be found in the c= and e= lines as shown below). Enable a 10046 trace at level 12 for the session - you will need the SID and SERIAL# from V$SESSION: EXEC SYS.DBMS_SYSTEM.SET_EV(SID,SERIAL#,10046,12,''); Let the process run and then manually review the trace file.

What you will end up with should look like this: PARSE #11:c=0,e=68,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=3413768266 WAIT #11: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=12475 tim=3413768503
WAIT #11: nam='SQL*Net message from client' ela= 439 driver id=1413697536 #bytes=1 p3=0 obj#=12475 tim=3413768994 BINDS #11:
kkscoacd
Bind#0
oacdty=96 mxl=32(03) mxlc=00 mal=00 scl=00 pre=00 oacflg=01 fl2=1000000 frm=01 csi=178 siz=64 off=0 kxsbbbfp=26d68b68 bln=32 avl=03 flg=05 value="AAA"
Bind#1
oacdty=96 mxl=32(01) mxlc=00 mal=00 scl=00 pre=00 oacflg=01 fl2=1000000 frm=01 csi=178 siz=0 off=32 kxsbbbfp=26d68b88 bln=32 avl=01 flg=01 value="U"
EXEC #11:c=0,e=269,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=3413769411 WAIT #11: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=12475 tim=3413769445
WAIT #11: nam='SQL*Net message from client' ela= 492 driver id=1413697536 #bytes=1 p3=0 obj#=12475 tim=3413769965 FETCH #11:c=0,e=190,p=0,cr=15,cu=0,mis=0,r=0,dep=0,og=1,tim=3413770213 WAIT #11: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=12475 tim=3413770275
WAIT #11: nam='SQL*Net message from client' ela= 1135 driver id=1413697536 #bytes=1 p3=0 obj#=12475 tim=3413771439 STAT #11 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=15 pr=0 pw=0 time=212 us)'

STAT #11 id=2 cnt=0 pid=1 pos=1 obj=12460 op='TABLE ACCESS BY INDEX
ROWID PAYABLE (cr=15 pr=0 pw=0 time=181 us)'
STAT #11 id=3 cnt=11 pid=2 pos=1 obj=12462 op='INDEX RANGE SCAN

X_PAYABLE_1 (cr=4 pr=0 pw=0 time=58 us)'

Pay close attention to the c=, e= and mis= on the PARSE, EXEC, and FETCH lines. In Oracle 9.2.0.5, divide the c= and e= numbers by 1000000 to determine CPU time in seconds and Elapsed time in seconds. mis= indicates a parse call (either hard or soft) - these are very expense, especially on EXEC and FETCH lines. The STAT lines indicate the row source execution plan. Hopefully, that is enough information to help you get started.

Charles Hooper
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc. Received on Thu Jun 14 2007 - 10:08:04 CDT

Re: v$wait_event: wait_time < 0