Diagnosing Locking Problems using ASH – Part 4

Some features in this post require a Diagnostics Pack license.

No sooner had I finished part 3 with some conclusions than I thought of another example I should have included and then someone else made a comment in an email which suggested another. (Thanks, JB!)

"It's probably worth pointing out that NO TOOL can claim to identify the blocking SID->SQL in such a case as there is no relationship kept in Oracle between locks acquired by users and the SQL that acquired the locks"

I’ll try to deal with that point and some other thoughts I had here in a further example. For this example, I decided to suggest how to create a quick table so that you can test this out for yourself.

SQL> create user testuser identified by testuser
  2  default tablespace USERS
  3  temporary tablespace TEMP;

User created.

SQL> grant create session, create table to testuser;

Grant succeeded.

SQL> connect testuser/testuser

Connected.

SQL> create table test_tab1 as select object_id pk_id, object_name from all_objects;

Table created.

As easy as that.

In the last part I showed that the SQL_ID for the last sample of a blocking session immediately before it went idle might not be the SQL statement holding the lock. In that case, it was fairly obvious that it wasn’t because it was a simple query that couldn’t have been responsible. However, it’s likely to be even more confusing if the SQL_ID captured by the ASH sample *looks* like it’s responsible, but isn’t, and the previous example didn't illustrate that clearly.

Session 1 – Connected as TESTUSER

SQL> select pk_id, object_name from test_tab1 order by pk_id desc for update;

<Trimmed>

       890 DBMS_STANDARD
       889 DBMS_STANDARD

     PK_ID OBJECT_NAME
---------- ------------------------------
       887 STANDARD
       886 RE$NV_LIST
       605 MAP_OBJECT
       319 STMT_AUDIT_OPTION_MAP
       317 STMT_AUDIT_OPTION_MAP
       316 TABLE_PRIVILEGE_MAP
       314 TABLE_PRIVILEGE_MAP
       313 SYSTEM_PRIVILEGE_MAP
       311 SYSTEM_PRIVILEGE_MAP
       259 DUAL
       258 DUAL

4477 rows selected.

SQL> rollback;

Rollback complete.

SQL> select pk_id from test_tab1 where object_name='SYSTEM_PRIVILEGE_MAP' for update;

     PK_ID
----------
       311
       313

SQL> rollback;

Rollback complete.

SQL> select pk_id from test_tab1 where pk_id=313 for update;

     PK_ID
----------
       313

SQL>

So session 1 has executed three different queries, all of which lock one or more rows including the row with PK_ID=313, has rolled back the first two (releasing the locks) and has just that row locked now.

Session 2 – Connected as TESTUSER

SQL> select pk_id from test_tab1 where pk_id=313 for update;

Session 2 hangs, waiting for the lock.

Session 1 – Connected as TESTUSER

SQL> rollback;

Rollback complete.

So the lock is released and session 2 acquires the lock and then releases it

Session 2 – Connected as Testuser

     PK_ID
----------
       313

SQL> rollback;

Rollback complete.

OK, time to look at the ASH data for the last two minutes for TESTUSER sessions. (Note that I have added each session’s serial# to the query. Graham Wood corrected a statement I made in the last post …

“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?”

… by pointing out that session_serial# would allow me to differentiate between different sessions where SID=148. I’ve updated the previous post to that effect.)

break on MY_TIME
column my_sid format 999
column my_ser format 99999
column my_state format a30
column my_blkr format 999
select to_char(a.sample_time, 'HH24:MI:SS') MY_TIME,a.session_id MY_SID,a.session_serial# MY_SER,
        DECODE(a.session_state, 'WAITING' ,a.event, a.session_state) MY_STATE,a.xid, a.sql_id,
        a.blocking_session MY_BLKR
from v$active_session_history a, dba_users u
where u.user_id = a.user_id
and u.username = 'TESTUSER'
and a.sample_time > SYSTIMESTAMP-(2/1440);

MY_TIME  MY_SID MY_SER MY_STATE                       XID              SQL_ID        MY_BLKR
-------- ------ ------ ------------------------------ ---------------- ------------- -------
12:53:01    300   2739 enq: TX - row lock contention                   2pa7rnqf65gj3     304
12:53:00    300   2739 enq: TX - row lock contention                   2pa7rnqf65gj3     304
12:52:59    300   2739 enq: TX - row lock contention                   2pa7rnqf65gj3     304
12:52:50    304   1445 ON CPU                         0006000E0000884D 95k0s60jznz76

So what statement is SQL_ID ‘95k0s60jznz76’?

SQL> select sql_text from v$sql where sql_id='95k0s60jznz76';

SQL_TEXT
-----------------------------------------------------------------------------
select pk_id, object_name from test_tab1 order by pk_id desc for update

Let’s face it, if you were to look at this data, how likely is it that you would think that that statement was responsible for blocking session 2, when it wasn't?