Wait Times

Doug's Oracle Blog

  • Home
  • Papers
  • Books
  • C.V.
  • Fun
  • Oracle Blog
  • Personal Blog

Jul 23: Wait Times

Sometimes you think a subject is understood so well, including by yourself, that you tend to overlook it until asked to explain it. That which seems intuitive to us might not be. I suspect Oracle's event instrumentation timing is one of those subjects.

I've become so used to looking at wait times in

  • Extended Trace Files (completed events); and
  • Active Session History (WAIT_TIME, TIME_WAITED and SESSION_STATE)

that it can throw me a little when developers are looking at V$SESSION_WAIT via TOAD's Session Monitor screen and asking me about what they see. It happened today. As one of the few areas that I think I feel entirely comfortable with (Z80 programming helps here, but only in having a low-level perspective on systems) I was surprised and disappointed to find myself finding things difficult to explain.

So I decided it was worth a blog post because I suspect what might seem obvious and old news isn't either to lots of people.

First, let's try the documentation. The Reference manual entry for V$SESSION_WAIT in 10.2

WAIT_TIME NUMBER A nonzero value is the session's last wait time. A zero value means the session is currently waiting.
SECONDS_IN_WAIT NUMBER If WAIT_TIME = 0, then SECONDS_IN_WAIT is the seconds spent in the current wait condition. If WAIT_TIME > 0, then SECONDS_IN_WAIT is the seconds since the start of the last wait, and SECONDS_IN_WAIT - WAIT_TIME / 100 is the active seconds since the last wait ended.
STATE VARCHAR2(19) Wait state:
  • 0 - WAITING (the session is currently waiting)

  • -2 - WAITED UNKNOWN TIME (duration of last wait is unknown)

  • -1 - WAITED SHORT TIME (last wait <1/100th of a second)

  • >0 - WAITED KNOWN TIME (WAIT_TIME = duration of last wait)



From that, I think we can safely say

If WAIT_TIME > 0, that's the wait time for the last event for this session which implies that the session is now running on CPU.

If WAIT_TIME = 0, it's currently waiting for whatever EVENT is contained in the EVENT column.

If WAIT_TIME = 0 and SECONDS_IN_WAIT is increasing, that's how long we're (still) waiting on this event.

If WAIT_TIME > 0 (indicating the last event completed) and SECONDS_IN_WAIT is > 0 and increasing (and this is the bit that tripped me up when talking to someone) SECONDS_IN_WAIT is the seconds since the start of the last wait, and SECONDS_IN_WAIT - WAIT_TIME / 100 is the active (my italics) seconds since the last wait ended.

Personally, and maybe it's just me, I find that idea of this column bizarre and not very useful unless WAIT_TIME=0. To put that another way, SECONDS_IN_WAIT is a strange name for a column that is sometimes actually showing you the number of seconds since the last wait! I must admit that I rarely use this column unless WAIT_TIME=0 and I'm looking at a 'stuck' session.

I should have noticed this today when someone described the situation as ...

I gather that wait_time = -1 and seconds in wait > 0, then it's usually doing something on the CPU
It's more that I'm watching the "seconds in wait" go up, whilst the "wait time" is -1 on db file sequential/scattered reads

So what that was really showing was that actually the session was very busy on CPU with the occasional I/O event. i.e. That constantly increasing SECONDS_IN_WAIT was actually a sign of 'this thing is sucking CPU'. I wouldn't mind so much, but I think the TOAD Session Monitor emphasises this column a little more than I would like. The bizarre thing from my own perspective is that I think I understand how this works pretty well, but that the column names and different states etc actually add to the confusion.

Oh, and what made me realise eventually where I was a) going wrong and b) explaining it badly was when I looked at the recent ASH samples, nearly all of which indicated the sesson was ON CPU.

Maybe you know all this already, but maybe it will help someone some day ....
Posted by Doug Burns Comments: (10) Trackbacks: (0)

Trackbacks
Trackback specific URI for this entry

PingBack
Weblog: www.pythian.com
Tracked: Jul 31, 22:32

Comments
Display comments as (Linear | Threaded)

#1 - Anonymous 2009-07-24 00:07 - (Reply)

When in doubt, doubt TOAD.
When ASH is available, use it.

#1.1 - Doug Burns said:
2009-07-24 06:59 - (Reply)

When ASH is available, use it.

Oh, don't say that. Now I'm just going to have another bunch of licensing comments! LOL

#2 - Jeff Moss said:
2009-07-24 12:59 - (Reply)

Nice post.

Just to be really picky, the view definition for V$SESSION_WAIT shows a very slight difference to the documentation:

(snipped from a 10.2.0.4 box, just the WAIT_TIME, SECONDS_IN_WAIT and STATE columns...don't have privs to check these are those columns, but I think I'm right)

CODE:
, decode(s.ksusstim,0,0,-1,-1,-2,-2,   decode(round(s.ksusstim/10000),0,-1,round(s.ksusstim/10000))) , s.ksusewtm , decode(s.ksusstim, 0, 'WAITING', -2, 'WAITED UNKNOWN TIME',  -1, 'WAITED SHORT TIME'       ,   decode(round(s.ksusstim/10000),0,'WAITED SHORT TIME','WAITED KNOWN TIME'))


KSUSSTIM is measured in microseconds, but the API shows the values in centiseconds(Millsap & Hall, Optimizing Oracle Performance), hence the 10000 division.

So, for the >0 values (of KSUSSTIM), if they are positive, but < 0.5 centiseconds, then it sets them to WAITED SHORT TIME rather than WAITED KNOWN TIME.

#2.1 - Jeff Moss said:
2009-07-24 12:59 - (Reply)

Jeff,

Sorry about that - no idea why this was rejected as spam. Added now.

Doug

#3 - Chris 2010-01-20 16:28 - (Reply)

Hi Doug,

"WAIT_TIME > 0 and SECONDS_IN_WAIT is > 0 and increasing"

From your explanation, my understanding is that in this case there is actually no wait, since the numbers essentially just show the length of the last wait.

So, why is this entry in this view if there is no actual wait at the current time?

#3.1 - Doug Burns said:
2010-01-21 06:22 - (Reply)

Chris,

Very quick answer would be ... because that's the way it works?

#3.1.1 - Chris 2010-01-21 09:00 - (Reply)

Hi Doug,

I think I realise where I was confused. I thought that v$session_waits shows only active waits, but you are saying that it shows the last wait for any active session (and therefore if the active session is not currently waiting it will show the last wait it experienced). Is that the case?

Thanks again for your time,

Chris

#3.1.1.1 - Doug Burns said:
2010-01-21 09:21 - (Reply)

Chris,

Yes, that's a good way of putting it. Would have probably put it that way myself if I'd taken the time to reply properly ;-)

Cheers,

Doug

#4 - ol 2010-03-01 14:56 - (Reply)

Thank you very much, because I didn't understand situation with 'wait_time = -1 and seconds in wait > 0'.
Is this situation (wait_time = -1 and seconds_in_wait > 0) always indicates that
session was on CPU (I/O event) ? Or wait event may be another?

#4.1 - Doug Burns said:
2010-03-05 07:43 - (Reply)

Does this section of the post cover your question?

"I gather that wait_time = -1 and seconds in wait > 0, then it's usually doing something on the CPU
It's more that I'm watching the "seconds in wait" go up, whilst the "wait time" is -1 on db file sequential/scattered reads

So what that was really showing was that actually the session was very busy on CPU with the occasional I/O event. i.e. That constantly increasing SECONDS_IN_WAIT was actually a sign of 'this thing is sucking CPU'."


I'm not sure what you mean by CPU (I/O) event. It's just CPU consumption here and the *last* event will be shown by the event name, but that's not what the session is waiting for now.


Add Comment

Standard emoticons like :-) and ;-) are converted to images.
E-Mail addresses will not be displayed and will only be used for E-Mail notifications.
BBCode format allowed
 
 

Statistics on Partitioned Tables

Contents

Part 1 - Default options - GLOBAL AND PARTITION
Part 2 - Estimated Global Stats
Part 3 - Stats Aggregation Problems I
Part 4 - Stats Aggregation Problems II
Part 5 - Minimal Stats Aggregation
Part 6a - COPY_TABLE_STATS - Intro
Part 6b - COPY_TABLE_STATS - Mistakes
Part 6c - COPY_TABLE_STATS - Bugs and Patches
Part 6d - COPY_TABLE_STATS - A Light-bulb Moment
Part 6e - COPY_TABLE_STATS - Bug 10268597

A couple of posts about Incremental Stats confusion

Part 1
Part 2

Comments

personal blog about Moving Sideways
Wed, 01.06.2016 17:34
That is a good tip particularl y to those fresh to the blogos phere. Short [...]
odziezprestige.pl about Moving Sideways
Wed, 01.06.2016 16:07
Please let me know if you're l ooking for a article writer fo r your site. [...]
Doug Burns about Moving Sideways
Tue, 10.05.2016 21:43
Oh, I won't give it that long unless I enjoy it ;-)

Bookmark

Open All | Close All

Syndicate This Blog

  • XML RSS 2.0 feed
  • ATOM/XML ATOM 1.0 feed
  • XML RSS 2.0 Comments
  • Feedburner Feed

Powered by

Serendipity PHP Weblog

Show tagged entries

xml 11g
xml ACE
xml adaptive thresholds
xml ASH
xml Audit Vault
xml AWR
xml Blogging
xml conferences
xml Cuddly Toys
xml Database Refresh
xml dbms_stats
xml Direct Path Reads
xml Fun
xml Grid Control
xml hotsos 2010
xml listener
xml locking
xml oow
xml oow2009
xml optimiser
xml OTN
xml Parallel
xml partitions
xml Patching
xml Swingbench
xml The Reality Gap
xml Time Matters
xml ukoug
xml ukoug2009
xml Unix/Shell
xml Useful Links

Disclaimer

For the avoidance of any doubt, all views expressed here are my own and not those of past or current employers, clients, friends, Oracle Corporation, my Mum or, indeed, Flatcat. If you want to sue someone, I suggest you pick on Tigger, but I hope you have a good lawyer. Frankly, I doubt any of the former agree with my views or would want to be associated with them in any way.

Design by Andreas Viklund | Conversion to s9y by Carl