Beyond Oracle Wait Interface – Part 2

This is the second part of the joint blog “project” with James Morle, called “The Wait Interface Is Useless (Sometimes)”.

We already did a joint presentation on this topic at UKOUG and more conferences will follow :) Read the first part by James here for intro.

So, where do we go when Oracle’s wait interface doesn’t help us? We will show multiple techniques over time, but here’s where I normally continue when wait interface is “useless”.

I use V$SESSTAT.

Oh, were you expecting something more “advanced” instead of boring old V$SESSTAT’s performance counters which has been available in Oracle for ages? ;-)

Well, there is a reason why the V$SESSTAT has been available in Oracle for ages, very likely even before Wait Interface was introduced (but I wouldn’t know for sure, I was still in elementary school back then or something :).

And the reason is that session level performance counters are VERY useful about finding out WHAT Oracle is doing. Every time you parse, a counter goes up by one in V$SESSTAT for the session. Every time you execute, a counter goes up. Every time you do a logical IO, a counter goes up. Every time you commit, a counter goes up. Every time an index block is split, a counter goes up. You get the point.

Oracle’s V$SESSTAT tells you WHAT Oracle is doing. Wait interface tells you how much TIME is spent waiting for something, but V$SESSTAT counters just tell you how many times some operation was done. You can not conclude how much time was spent by looking just at the number of times something has happened (as Cary will tell you) but nevertheless, the V$SESSTAT counters definitely give you a good clue into WHAT THE [FU|HE]CK is an Oracle session doing – especially when wait interface says you’re not waiting for anything and SQL trace doesn’t print a line.

How many different operations are counted for each session in Oracle? Let’s check (Oracle 11.2):


SQL> select count(*) from v$sesstat where sid = 14;

COUNT(*)
----------
611

Oracle 11.2 keeps track of the counts of 611 different operations, for each session!

That’s VERY valuable source of information for understanding what Oracle is doing and its relatively easy to use.

And that’s exactly the reason why I wrote my Snapper script – I wanted this information to be VERY EASY to use!

And here’s an example – session 14 is stuck, doesn’t respond, user complains. Let’s check the wait interface:

If I want to know what a session is doing, I sample V$SESSION_WAIT first, with my sw.sql script (or I could just query ASH which gives me the same data with history):

SQL> @sw 14

    SID STATE   EVENT                                          SEQ# SEC_IN_WAIT P1                 P2                 P3                 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
     14 WORKING On CPU / runqueue                              3486         130

1 row selected.

SQL>
SQL> @sw 14

    SID STATE   EVENT                                          SEQ# SEC_IN_WAIT P1                 P2                 P3                 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
     14 WORKING On CPU / runqueue                              3486         137

1 row selected.

SQL>
SQL>
SQL> @sw 14

    SID STATE   EVENT                                          SEQ# SEC_IN_WAIT P1                 P2                 P3                 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
     14 WORKING On CPU / runqueue                              3486         139

1 row selected.

SQL>

From here we see 2 things:

  1. 3 samples out of 3 the session was ON CPU (not waiting). 3 samples is not too good for precise statistical sampling but there’s something else I spot in the output
  2. SEC_IN_WAIT (read: seconds in current state) is over 130. This means that this session has been in the current state (ON CPU) for over 130 seconds in row, without waiting for anything in between (the moment the wait state changes, the SEC_IN_WAIT goes back to 0).

So, it’s pretty evident that this session is just burning CPU and wait interface is useless here (as we are not waiting for anything, as far as Oracle sees it of course). Alternatively I could just run top or prstat and check whether the process is 100% on CPU or not.

So, before going on to Snapper, lets look into what kind of SQL this session executes right now (we could sample this also multiple times, to check whether we are constantly running the same statement):

SQL> <strong>select * from table(select dbms_xplan.display_cursor(sql_id,sql_child_number) from v$session where sid = 14);</strong>

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  5vy5qjd3fsn5c, child number 0
-------------------------------------
SELECT     MIN(t1.created), MAX(t1.created) FROM     t1   , t2   , t3
WHERE     t1.object_id = t2.object_id AND t2.object_id = t3.object_id
AND t1.owner = :v AND t2.owner = :v AND t3.owner = :v

Plan hash value: 3271631391

----------------------------------------------------------------------------------------
| Id  | Operation                       | Name | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |      |       |       |     4 (100)|          |
|   1 |  SORT AGGREGATE                 |      |     1 |    66 |            |          |
|*  2 |   HASH JOIN                     |      |     7 |   462 |     4  (25)| 00:00:01 |
|   3 |    NESTED LOOPS                 |      |       |       |            |          |
|   4 |     NESTED LOOPS                |      |     7 |   329 |     2   (0)| 00:00:01 |
|   5 |      TABLE ACCESS BY INDEX ROWID| T1   |     7 |   196 |     1   (0)| 00:00:01 |
|*  6 |       INDEX RANGE SCAN          | I1   |     7 |       |     1   (0)| 00:00:01 |
|*  7 |      INDEX RANGE SCAN           | I2   |    27 |       |     1   (0)| 00:00:01 |
|*  8 |     TABLE ACCESS BY INDEX ROWID | T2   |     1 |    19 |     1   (0)| 00:00:01 |
|   9 |    TABLE ACCESS BY INDEX ROWID  | T3   |    40 |   760 |     1   (0)| 00:00:01 |
|* 10 |     INDEX RANGE SCAN            | I3   |    40 |       |     1   (0)| 00:00:01 |
----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

2 - access("T2"."OBJECT_ID"="T3"."OBJECT_ID")
6 - access("T1"."OWNER"=:V)
7 - access("T2"."OWNER"=:V)
8 - filter("T1"."OBJECT_ID"="T2"."OBJECT_ID")
10 - access("T3"."OWNER"=:V)

33 rows selected.

SQL>

Hmm… can anyone reliably tell why this SQL statement is slow and burns all the CPU time?

The answer is no. An execution PLAN is a plan of actions which would be executed when someone runs the execution plan. It doesn’t tell you anything about what’s exactly going on right now, it doesn’t tell you what exactly is using all the CPU time. Anything we would say at this point, would be a guess! Lets use V$SESSTAT instead, for gathering more hard evidence!

(The syntax of Snapper is documented inside the script or just search for snapper in my blog, plenty of examples :)

SQL> <strong>@snapper out 5 1 14
</strong>
-- Session Snapper v2.02 by Tanel Poder ( http://www.tanelpoder.com )

--
----------------------------------------------------------------------------------------------------------------------
  SID, USERNAME  , TYPE, STATISTIC                               ,         DELTA, HDELTA/SEC,    %TIME, GRAPH
----------------------------------------------------------------------------------------------------------------------
   14, SYS       , STAT, session logical reads                   ,         81351,     16.27k,
   14, SYS       , STAT, consistent gets                         ,         81351,     16.27k,
   14, SYS       , STAT, consistent gets from cache              ,         81351,     16.27k,
   14, SYS       , STAT, consistent gets from cache (fastpath)   ,         81352,     16.27k,
   14, SYS       , STAT, no work - consistent read gets          ,         81381,     16.28k,
   14, SYS       , STAT, table fetch by rowid                    ,       2904784,    580.96k,
   14, SYS       , STAT, index scans kdiixs1                     ,            93,       18.6,
   14, SYS       , STAT, buffer is pinned count                  ,       5736560,      1.15M,
   14, SYS       , STAT, buffer is not pinned count              ,         75248,     15.05k,
   14, SYS       , STAT, no buffer to keep pinned count          ,             1,         .2,
   14, SYS       , TIME, DB CPU                                  ,       6050000,      1.21s,   121.0%, |@@@@@@@@@@|
   14, SYS       , TIME, sql execute elapsed time                ,       6059922,      1.21s,   121.2%, |@@@@@@@@@@|
   14, SYS       , TIME, DB time                                 ,       6059922,      1.21s,   121.2%, |@@@@@@@@@@|
--  End of snap 1, end=2010-01-15 17:33:22, seconds=5

PL/SQL procedure successfully completed.

As our previous sw.sql output showed  – we are not waiting for anything. If we were, then snapper would show you WAIT lines from wait interface (V$SESSION_EVENT) as well. But we don’t see any waits.

So, now its the time to go through all the V$SESSTAT stats reported in Snapper! These are the lines with STAT in them (TIME lines are V$SESS_TIME_MODEL breakdown available since 10g, but they are not detailed enough for diagnosing complex problems).

One thing we see, there is a statistic session logical reads and from the last column of Snapper output we see that this session did over 16000 logical reads (buffer gets) per second during snapper run time (of 5 seconds). That’s already a good indication of why we burn so much CPU time – we are doing lots of logical IOs.

Also, we see that we did 18.6 index range scans per second (the statistic index scans kdiixs1 shows that). That doesn’t seem “much” does it. However, check the value for buffer is pinned count statistic! This counter is updated every time we go to a buffer to get some data from it AND it already happens to be open by my session! Oracle keeps buffers pinned  and relevant buffer handles cached during a database call in some cases (like nested loop joins and index scans) to avoid reopening the buffer again (getting a buffer again if its closed would mean another logical IO).

Nevertheless, we can see that we re-visited some buffers again and again and again – over a million times per second! When checking my index structures I see that every index has only a few hundred blocks, so having millions and millions of buffer visits (buffer is pinned count + session logical reads) means we are heavily re-visiting the same blocks again and again and again! This points directly to NESTED LOOPS (and also INDEX RANGE SCANS) in the execution plan. Nested loops, as the name says loops through inner rowsource and revisits some of its data as many times as the number of rows coming from the outer rowsource (with few special cases, as usual).

And there’s one more statistic in Snapper output which I do NOT see – execute count. This statistic shows how many times the session executed cursors (executed new ones or re-executed the same one). NB! Snapper only reports these V$SESSTAT statistics which changed during the snapshot – as execute count is not reported, it means that the execute count did not increase during the snapshot, thus the session still executed the same statement! (so for example we were not hard parsing and lots of different statements to “justify” this CPU usage, Snapper would have shown parse count (hard) going up if this session had done so).

So, using the above diagnosis, this is the place where I would take a serious look whether the NESTED LOOPS in the above execution plan are a right thing to do. I would check how many rows would actually match the bind variable values (more about that later) in the SQL statement predicates – NESTED LOOPS is not a good operation for joining large number of rows. More about SQL tuning very soon ;-)

To finish this blog entry, this is the sequence of troubleshooting which I usually use (if a user complains or “something” is slow):

  1. Identify the session(s) servicing the user/task with the problem
  2. Check wait interface for these sessions (sw.sql, ASH query) – this gives quick overview whether the session is 100% stuck waiting for something, 100% busy working and burning CPU or somewhere in between
  3. Run Snapper on the sessions to (very easily) see which V$SESSTAT counters have gone up (some counters such memory usage and open cursors current can go down too)
  4. If all this fails or doesn’t give enough evidence of the problem for whatever reason, then it’s time to take a screwdriver and open up Oracle from outside – using stack traces, truss, DTrace etc. We will be blogging about this ;-)

Note that Snapper is just an anonymous PL/SQL block and it doesn’t require any changes to the database!

Ok, back to James now!

Note that this year’s only Advanced Oracle Troubleshooting class takes place in the end of April/May 2014, so sign up now if you plan to attend this year!

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

24 Responses to Beyond Oracle Wait Interface – Part 2

  1. Thank you Tanel for reminding me there is more than waits (in trace, ash,…)

    Just one question: is it sufficient in sampling @sw 14 to see “event” AND “seq#” staying the same to infer the session is still within the _same_ event (and therefore execution of the same statement)?
    As you mentioned this question twice (before dbms_xplan.display_cursor and in the absence of “execute count” and “parse count (hard)” I’m insecure.

  2. coskan says:

    Right on time, James was nearly giving up expecting the second part from you because of your tight schedule (I think we can say you were on CPU) :)

    Thanks for sharing

  3. Tanel Poder says:

    Yeah I told James that I wouldn’t be able to write anything for couple of weeks… and then James asked if I have some good examples of using v$sesstat or snapper in my blog … and I thought to quickly write one :)

    @Martin:

    If you see the same event and seq# AND seconds_in_wait only goes upwards then you are in the same WAIT STATE (either waiting for an event to complete or not waiting at all, but working on CPU).

    v$session_wait doesn’t know anything about executions directly. You can have a situation where you execute lots of statements in a loop (and these statements dont wait for anything), then you’ll constantly be ON CPU and the seq# will be the same.

    So you can execute many different statements while still being ON CPU and having the same seq# in v$session_wait.

    Note that the seq# is just a 2-byte value, thus it will wrap back to 0 after it reaches 65535. That’s why I don’t use seq# as a first thing to check, but will look into seconds_in_wait instead. If seconds_in_wait is constantly 0 (the granularity is 1 second) then it should mean that all of the waits (or continuous CPU usage “slices” between waits) take less than a second at a time. In such cases you can see how fast the seq# changes to determine whether you have something like a couple of 0.5sec waits per second happening or hundreds of 0.002 second waits instead. V$SESSION_EVENT is helpful in such cases as you can calculate average event duration from there.

  4. Tanel Poder says:

    To recap, if you want to see whether you are still in the same WAIT STATE, then use V$SESSION_WAIT (sw.sql)

    If you want to know whether you are still in the same EXECUTE, then use “execute count” from V$SESSTAT.

    However the full picture is more complex, you can execute statement A and B once, keep the cursors open and now fetch few lines from A, then B, then more lines from A again, then B again and so on.

    So, you have executed both statements only once, but now you can fetch the rows from these statements a bit at a time, effectively running parts of execution plan A first, then running parts of B, then A, then B without having to constantly execute the statements again.

    However, if you have multiple FETCH calls like mentioned above, then there’s another statistic called “user calls” which is incremented at every user OPI call (parse,execute,fetch,describe,OCI direct commit,etc) so its possible to get an idea whether there’s fetching going on… Of course, when a fetch call completes and results are sent back to application then sql_trace would trace that and you’d see SQL*Net… wait events…

    With this article I wanted to illustrate how much additional diagnostics info there is in V$SESSTAT and how easy it is to get there. No need for tracing, undocumented events etc, well at least I never use such stuff as a starting point as there are easier ways to troubleshoot.

  5. Statistique says:

    Good stuff from Tanel, as usual. This guy is like crack for me, can’t get enough ! Thanks for sharing this with us.

  6. mdinh says:

    Very nice and thanks for sharing.

  7. mdinh says:

    Would you be able to provide the SQL script to create this scenario?

  8. Tanel Poder says:

    mdinh, yep I will post the script soon with an explanation!

  9. Enrique Aviles says:

    Excellent information. This shows there is always something new to learn in the Oracle world. Thanks!!

  10. Simon Palmer says:

    Excellent, as usual… Thanks Tanel.

    Regards,

    Simon

  11. Narendra says:

    Tanel,

    WOW !!!!
    I can not stress how much I liked the way you walked us (readers) through an analysis which started with V$ views’ contents and how they can be pieced together to arrive at the “root cause”. Thanks a zillion! As always, learned something new today.

  12. Pingback: The Oracle Wait Interface Is Useless (sometimes) – part 3a « James Morle's Blog

  13. Sam says:

    Thanks Tanel, I open my eyes! I have been running to waits/statspack/awr reports to find something when session is consuming resources doing nothing. I could find nothing, your blog explains that!

  14. Pingback: Bind Variable Peeking – execution plan inefficiency | Tanel Poder's blog: Core IT for Geeks and Pros

  15. Pingback: Blogroll Report 08/01/2009 – 15/01/2010 « Coskan’s Approach to Oracle

  16. Pingback: The Oracle Wait Interface Is Useless (sometimes) – part 3b « James Morle's Blog

  17. Wojciech says:

    Tanel, I am impressed by this doc and your style. Well done.

    One thing is not clear to me. I have always thought that when CPU is busy with logical reads and consistent gets there should be also many IO events in the meantime like ‘db file sequential read’. They are just to put the blocks into SGA before it goes to CPU. I just wonder how is that possible that CPU works on logical reads continually for minutes and a single ‘db file sequential read’ doesn’t happen. What exactly a ‘logical read’ on CPU is/does?

    I am just a begginer of oracle internals so would appreciate if you put some light on it.

  18. Pingback: The Oracle Wait Interface Is Useless – part 3b | Scale Abilities

  19. Pingback: The Oracle Wait Interface Is Useless Part One: The Problem Definition | Scale Abilities

  20. Pingback: The Oracle Wait Interface Is Useless - part 3a | Scale Abilities

  21. gianni says:

    Hi,
    there is a way to know session statistics but in the past?
    v$sesstats but in the past?

    br,

    gianni

    • Tanel Poder says:

      Nope, unless you capture these yourself somehow. I once wrote a tool called Sesspack for this (it’s in my blog somewhere), but it’s not tested on 11g+.

      ASH in 11.2 does have a few session level metrics in it, but only a handful:

      DELTA_READ_IO_REQUESTS
      DELTA_WRITE_IO_REQUESTS
      DELTA_READ_IO_BYTES
      DELTA_WRITE_IO_BYTES
      DELTA_INTERCONNECT_IO_BYTES
      PGA_ALLOCATED
      TEMP_SPACE_ALLOCATED

      There’s also V$SESSMETRIC and DBA_HIST_SESSMETRIC_HISTORY, but the first doesn’t have too many metrics in it and the second one seems to capture history only under special circumstances (basically doesn’t do what you asked for).

      So, if you want to store detailed session level metrics over time, then write some PL/SQL code, check out Sesspack or use snapper with trace option if you only need this temporarily …

  22. Pingback: Bringing Oracle Sales to the Table - Steve Karam :: The Oracle Alchemist

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>