Jul 23: Wait Times
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:
|
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 ....
#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)
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.
Tracked: Jul 31, 22:32