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