Diagnosing Locking Problems using ASH - Part 3

Some features in this post require a Diagnostics Pack license.

In the last part I described a locking scenario where the blocking session had only executed one SQL statement that was quick enough to avoid being sampled by ASH and is now inactive. As a result, there is no ASH data for the blocking session, so diagnosing the root cause of the problem after the event is next to impossible. In fairness, it would be impossible anyway without ASH or similar instrumentation.

However, as I suggested in that post, I would argue that's a fairly unusual situation arising out of the nature of the demo and that the blocking session would normally appear in ASH. So let's try a more realistic situation where the blocking session does more work.

Session 1 - logged in as TESTUSER

TESTUSER@TEST1020> select count(*) from test_tab1;

  COUNT(*)
----------
   1024000

TESTUSER@TEST1020> select pk_id from test_tab1 where rownum=1 for update;

     PK_ID
----------
      4051

So this time, I ran a simple query before the SELECT FOR UPDATE. Session 1 holds a lock on that row and I'll use the PK_ID that was returned from the query to make sure I try to lock the same row in the next session.

Session 2 - logged in as TESTUSER

TESTUSER@TEST1020> select pk_id from test_tab1 where pk_id=4051 for update;

Session 2 hangs, waiting for session 1 to release the lock

Session 1 - commits, to release the lock

TESTUSER@TEST1020> commit;

Commit complete.

Session 2 - Is now able to acquire the lock, so locks the row and returns the result

     PK_ID
----------
      4051

So everything about this test is the same as the last post, but Session 1 is doing a little more work than the simple SELECT FOR UPDATE. Let's look at the ASH data for all TESTUSER sessions.

SYS@TEST1020> select a.sample_id,a.sample_time,a.session_id,
  2             a.session_state,a.event,a.sql_id,
  3     a.blocking_session,a.blocking_session_status
  4  from v$active_session_history a, dba_users u
  5  where u.user_id = a.user_id
  6* and u.username = 'TESTUSER';

 SAMPLE_ID
----------
SAMPLE_TIME
---------------------------------------------------------------------------
SESSION_ID SESSION
---------- -------
EVENT                            SQL_ID        BLOCKING_SESSION BLOCKING_SE
-------------------------------- ------------- ---------------- -----------
    445637
30-MAR-09 22.23.59.263
       147 ON CPU
                                 0ut22yp7mh229                  NOT IN WAIT

    445636
30-MAR-09 22.23.58.253
       147 WAITING
enq: TX - row lock contention    0ut22yp7mh229              148 VALID

    445635
30-MAR-09 22.23.57.253
       147 WAITING
enq: TX - row lock contention    0ut22yp7mh229              148 VALID

    445634
30-MAR-09 22.23.56.253
       147 WAITING
enq: TX - row lock contention    0ut22yp7mh229              148 VALID

    445633
30-MAR-09 22.23.55.252
       147 WAITING
enq: TX - row lock contention    0ut22yp7mh229              148 VALID

    445611
30-MAR-09 22.23.33.181
       148 WAITING
db file scattered read           cda14zb83bb5u                  NO HOLDER

    445610
30-MAR-09 22.23.32.181
       148 WAITING
db file scattered read           cda14zb83bb5u                  NO HOLDER

    445609
30-MAR-09 22.23.31.181
       148 WAITING
db file scattered read           cda14zb83bb5u                  NO HOLDER

    445608
30-MAR-09 22.23.30.181
       148 WAITING
db file scattered read           cda14zb83bb5u                  NO HOLDER


9 rows selected.

This time I'm going to work my way from the top of the data to the bottom (or from the most recent data to the oldest).

The most recent sample shows session 147 on CPU but immediately prior to that, I can see that it was stuck waiting for a TX row lock since some time between 22:23:54 and 22:23:55 and that the blocking session was 148. Things are a little better this time because there are samples for the blocking session 148 but, if I look at the ASH sample immediately prior to the locking problem, session 148 is executing SQL_ID "cda14zb83bb5u'. If I check which SQL statement that is

SYS@TEST1020> select sql_text from v$sql where sql_id='cda14zb83bb5u';

SQL_TEXT
--------------------------------------------------------------------------------
select count(*) from test_tab1

Which isn't the statement that was holding the lock. I've hit the same problem as the previous example because the SELECT FOR UPDATE activity wasn't sampled.

The up-side to this example is that I can at least see some information about the blocking session in the lead-up to the locking problem. That could be very useful in identifying who the user was, what application they were running, which module they were executing and so on. (Then again, who is to say that that session 148 is the same session as the blocking session 148 and not an earlier session that has disconnected? Updated later - as Graham Wood pointed out, I could have used SESSION_SERIAL# to ensure that I am looking at the right session 148.)

The down-side is that it's easier to fool yourself into thinking you're looking at the root cause of the problem, when you aren't. In this case, it wouldn't take long to realise that the simple query is not blocking the other session and that there must be something missing, but imagine if the SQL had been a transactional statement that could be the source of the problem, but wasn't?

Conclusion
I started off the first post by saying "There are few better illustrations of the utility of ASH data than the ability to detect and diagnose locking problems, even after they've occurred" and I still think that's true. Diagnosing concurrency problems without having access to information on all sessions is next to impossible and ASH's low-cost sampling approach to recording session activity is the very reason it can be switched on all the time, waiting for problems to occur. Of course, the nature of sampling implies an approximate view of reality (and I've deliberately picked examples here to illustrate the gaps in the approximation).

- If the problem is happening right now, then you will have all the information you need, whether you have ASH data or not

- If the blocking SQL statement runs for more than a second because it's resource intensive or is experiencing it's own bottleneck, then you'll have good samples of the root cause.

- If the blocking SQL statement runs in less than a second then you might have an ASH sample of it or you might not, but then you might have samples covering previous actions that could help diagnose the problem.

- Or you could be unlucky, as I was last week, and have no samples at all
I also said in the first post that ASH data "has proved very useful to me in solving several production performance problems in the past" and that still holds true. It just works better with some problems than others and you need to be aware of it's limitations if you're going to use it.