Another use case for WaitProf – diagnosing “events in waitclass Other”

I recently diagnosed a performance issue where the “events in waitclass Other” occasionally took significant part of the session’s response time. For example Snapper (which reads wait event data from V$SESSION_EVENT) reported that during measuring 39.9% of the response time was spent on “events in waitclass Other”.

SQL> @sn 1 119

-- Session Snapper v1.07 by Tanel Poder ( http://www.tanelpoder.com )

---------------------------------------------------------------------------------------------------------------------------------------------
HEAD,     SID, SNAPSHOT START   ,  SECONDS, TYPE, STATISTIC                               ,         DELTA,  DELTA/SEC,     HDELTA, HDELTA/SEC
---------------------------------------------------------------------------------------------------------------------------------------------
DATA,     119, 20080621 05:22:05,        1, STAT, session logical reads                   ,         18284,      18284,     18.28k,     18.28k
DATA,     119, 20080621 05:22:05,        1, STAT, consistent gets                         ,         15301,      15301,      15.3k,      15.3k
DATA,     119, 20080621 05:22:05,        1, STAT, consistent gets from cache              ,         15228,      15228,     15.23k,     15.23k
DATA,     119, 20080621 05:22:05,        1, STAT, consistent gets from cache (fastpath)   ,         15136,      15136,     15.14k,     15.14k
DATA,     119, 20080621 05:22:05,        1, STAT, calls to get snapshot scn: kcmgss       ,            89,         89,         89,         89
DATA,     119, 20080621 05:22:05,        1, STAT, no work - consistent read gets          ,         14883,      14883,     14.88k,     14.88k
DATA,     119, 20080621 05:22:05,        1, STAT, table scans (short tables)              ,            21,         21,         21,         21
DATA,     119, 20080621 05:22:05,        1, STAT, table scan rows gotten                  ,       1429227,    1429227,      1.43M,      1.43M
DATA,     119, 20080621 05:22:05,        1, STAT, table scan blocks gotten                ,         17440,      17440,     17.44k,     17.44k
DATA,     119, 20080621 05:22:05,        1, WAIT, events in waitclass Other               ,        399831,     399831,   399.83ms,   399.83ms
--  End of snap 1

From Oracle 10g Oracle has consolidated lots of the events into “events in waitclass Other”. This is because saving all 900+ wait event stats for every session (in V$SESSION_EVENT array) would waste too much memory with giving little benefit (normally there’s only a handful of troublemaking events anyway). Therefore makes sense to aggregate the least likely happening events under some common category. Looks like Oracle kernel coders have set a threshold in event number above which all events are grouped under the “other” waitclass.

See below, this is from 11g:

SQL> select count(*) from v$event_name;

  COUNT(*)
----------
       961

SQL> select wait_class, count(*) from v$event_name group by wait_class;

WAIT_CLASS                                                         COUNT(*)
---------------------------------------------------------------- ----------
Concurrency                                                              26
System I/O                                                               23
User I/O                                                                 22
Administrative                                                           51
Other                                                                   632
Configuration                                                            21
Scheduler                                                                 3
Cluster                                                                  47
Application                                                              15
Queueing                                                                  4
Idle                                                                     80
Network                                                                  35
Commit                                                                    2

13 rows selected.

There is total 961 different wait events in this version of Oracle, but 632 of these are categorized under “other” name.

So, what to do when this “events in waitclass Other” wait becomes significant in the response time profile?

Actually it’s simple. Only the V$SESSION_EVENT experiences this issue of event aggregation, V$SESSION_WAIT (and sql_tracing) do not. The reason (again) is that unlike V$SESSION_EVENT, the V$SESSION_WAIT view does not have to store the cumulative stats in somewhere memory, therefore aggregation for memory savings is not needed there.

So, let’s use my WaitProf to check what’s the real event my session is waiting for:

SQL> @waitprof print 119 e123 1000000

-- WaitProf 1.04 by Tanel Poder ( http://www.tanelpoder.com )

                                                                                                                          % Total  Total Event   Distinct   Avg time
    SID STATE   EVENT                               P1                         P2              P3                    SEQ#    Time      Time ms     Events   ms/Event
------- ------- ----------------------------------- -------------------------- --------------- --------------- ---------- ------- ------------ ---------- ----------
    119 WORKING On CPU / runqueue                                                                                           78.04    13056.393          1  13056.393
    119 WAITING latch free                          address= 000000005E60BE28  number= 148     tries= 0                     21.96     3673.607          1   3673.607

Elapsed: 00:00:16.73

See, it’s actually waiting for a “latch free” event!

What is this latch?

SQL> @la 5E60BE28

ADDR         LATCH#   CHLD NAME                                           GETS      IGETS     MISSES    IMISSES     SLEEPS  WAIT_TIME
-------- ---------- ------ ---------------------------------------- ---------- ---------- ---------- ---------- ---------- ----------
5E60BE28        148      6 simulator lru latch                        16718933          3     144011          0       3456 1894137768

And we found that this is a buffer cache simulation (V$DB_CACHE_ADVICE) related latch!

To be honest, I kind of knew what the issue was already – I noticed that the servers CPUs were already 100% utilized and the CPU runqueues were quite lenghty. Once you have 100% CPU usage and runqueues start to build up, you will start seeing latch contention on solitary latches and latches with only few children. This is mostly due that if the unlucky event happens that a latch holder is scheduled off CPU then it may take tens or hundreds of milliseconds before the holder gets back to CPU to complete its work and release the latch. However it’s likely that during that time many other processes try to grab the latch and start spinning on it. This raises the CPU usage even more. In this db there thousands of cache buffers chains latches, but only 16 of simulator lru latches. Therefore, even if a CBC latch holder went to sleep, the likelyhood of a collision was quite unlikely than in a similar case with simulator lru latch holder.

This brings me to point that whenever you see any latch contention (especially unusual one) in your performance tool output, first check the CPU utilization. High CPU usage (due execution plan gone bad, parallelism kicking in unexpectedly etc) can cause latch contention and in those conditions the “latch free” events are just a symptom of your real problem.

Anyway, I was writing about “events in waitclass Other”, not latches today, so few more points on events:

I have a script which queries V$FIXED_VIEW_DEFINITION to see the contents of V$ views – and I check out on what X$ table is V$SESSION_EVENT based:

SQL> @v gv$session_event

VIEW_NAME                      TEXT
------------------------------ ----------------------------------------------------------------------------------------------------
GV$SESSION_EVENT               select s.inst_id, s.kslessid, d.kslednam, s.ksleswts, s.kslestmo, round(s.kslestim / 10000),
                               round(s.kslestim / (10000 * s.ksleswts), 2), round(s.kslesmxt / 10000),  s.kslestim, d.ksledhash,
                               d.ksledclassid, d.ksledclass#, d.ksledclass  from x$ksles s, x$ksled d  where s.ksleswts != 0 and
                               s.kslesenm = d.indx


SQL>

X$KSLES stores the session level wait event stats.
X$KSLED stores the event names (as X$KSLES doesn’t store the event name itself but just its ID)

So, we check how many V$SESSION_EVENT records we have for session 119:

SQL> select count(*) from x$ksles where kslessid = 119;

  COUNT(*)
----------
       331

SQL>

331 records only for this session.

But, as I showed above, V$EVENT_NAME which is based on X$KSLED had 900+ event names in it.

So lets see what events do we see after event# 331:

SQL> select indx, kslednam from x$ksled where indx > 331;

      INDX KSLEDNAM
---------- ---------------------------------------------------------
       332 latch free
       333 unspecified wait event
       334 latch activity
       335 wait list latch activity
       336 wait list latch free
       337 kslwait unit test event 1
       338 kslwait unit test event 2
       339 kslwait unit test event 3
       340 global enqueue expand wait
       341 free process state object
       342 inactive session
       343 process terminate
       344 latch: session allocation
       345 check CPU wait times
       346 enq: CI - contention
       347 enq: PR - contention
       348 ksim generic wait event
       349 debugger command
       350 ksdxexeother
       351 ksdxexeotherwait
       352 enq: PE - contention
       353 enq: PG - contention
       354 ksbsrv
[...snipped...]

Most of the events are quite unknown ones, but it looks like latch free is also in one of the “other” ones now!
That explains why Snapper showed “events in wait class Other” instead of latch free.

Note that V$SYSTEM_EVENT doesn’t have that event aggregation issue – as you need to store systemlevel wait stats only in one location in instance (and not for each session).

V$SYSTEM_EVENT is based on X$KSLEI:

SQL> select count(*) from x$kslei;

  COUNT(*)
----------
       961

That’s pretty much all for today, but theres one more think I want to show, related to X$ table quirks. As V$ views and X$ tables are not normal tables (but rather structure definitions and pointers to underlying functions), they don’t have to play according to normal table rules. Check this:

SQL> select min(indx),max(indx) from X$ksles where kslessid in (1);

 MIN(INDX)  MAX(INDX)
---------- ----------
         0        330

SQL> select min(indx),max(indx) from X$ksles where kslessid in (2);

 MIN(INDX)  MAX(INDX)
---------- ----------
         0        330

You see that regardless of the parameter I pass to the query, I do get min and max values of 0 and 330 in INDX column.

SQL> select min(indx),max(indx) from X$ksles where kslessid in (1,2);

 MIN(INDX)  MAX(INDX)
---------- ----------
         0        661

However if I pass both parameters together, then the max value reaches 661.

SQL> select min(indx),max(indx) from X$ksles where kslessid in (1,2,3);

 MIN(INDX)  MAX(INDX)
---------- ----------
         0        992

If I add third value, the max(indx) goes up to 992… however If I use only 3rd value (which caused the max to go up to 992), then the max goes down to 330:

SQL> select min(indx),max(indx) from X$ksles where kslessid in (3);

 MIN(INDX)  MAX(INDX)
---------- ----------
         0        330

This illustrates that the INDX column in X$ tables is quite like ROWNUM in normal tables. Actually, the INDX (as the name says) is the index into underlying X$ table array. However as this X$ table was a “dynamic” one which was not based on a fixed SGA structure directly but really called an intermediate X$ service function, which fetched only the required data from SGA and placed it into an array in UGA, the INDX represents the slot in the result UGA array, not SGA one ;)

I’ll write about identifying different variations of X$ tables in a future post ;)

This entry was posted in Oracle and tagged , , , . Bookmark the permalink.

7 Responses to Another use case for WaitProf – diagnosing “events in waitclass Other”

  1. Awesome post. I have been seeing just about every 10g database we have with a warning for the ‘OTHER’ wait group in Grid control. I knew there were a ton of waits aggregated under it, but at least now I have some ammunition into diving into the true issues, if they exist.

  2. tanelp says:

    Thanks! Yep, normally you shouldn’t see any significant waits from the Other group (that’s why they all are consolidated there), but there are always some corner cases…

  3. lscheng says:

    Hi Tanel

    I have observed in your script that when process is waiting you use CPU / runqueue to show as wait event.

    Do you know if in a CPU bounded system Oracle can account more DB CPU time than it actually uses? i.e Can Oracle report more CPU usage (in Oracle statistics such as DB CPU or CPU Used by this session) than it really uses?

  4. Tanel Poder says:

    Yes as if an Oracle session is not waiting for anything then it ought to be on CPU (or at least try to be on it).

    The exceptions are instrumentation bugs where Oracle actually is waiting for some syscall to complete without reporting it in wait event and also suspended processes.

    Regarding your other question – Oracle does not report more CPU usage than actually used if you query the right views (like V$SYS_TIME_MODEL DB CPU or even V$SYSSTAT session cpu usage). The data you see in these views comes straight from OS, Oracle asks CPU usage info via times() syscalls on Unixes.

    Now if we talk about v$session_wait, ASH etc, yes they can account more CPU usage than there’s CPU time available, because Oracle thinks even CPU scheduling latency is CPU usage.

  5. Tanel Poder says:

    So, things like ASH & v$session_wait are not good for determining CPU usage. In fact, if you want to get the correct picture, use vmstat or an OS tool.

  6. lscheng says:

    Aha, I thought Oracle count as CPU usage when it is waiting in the runqueue (for the time model)

    So in ASH it can actually get wrong CPU usage

    Great, thanks for the tips!

  7. Paresh says:

    Hi Tanel,

    Excellent post. I have a few questions directly and indirectly related to main topic of this post:

    1) Is it possible for a process to get evicted off the CPU while holding a latch? I thought a) latches are held for a extremely short period of time and b) there is some kind of mechanism in Unix/Linux to “beg” some extra CPU cycles from the OS during this critical slot so as not to get evicted in middle of a crucial operation

    2) How can I get definition (SQL) of v$ views from fixed_view_definition when the SQL length is > 4000 characters (e.g. for v$session)?

    Thanks,
    Paresh

Leave a Reply

Your email address will not be published. Required fields are marked *

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>