Diagnosing Locking Problems using ASH – Part 5

... and so it continues.

Coincidentally, the subject of tracking down locking problems after they occurred cropped up on the Oak Table mailing list just after the last post. Several suggestions were offered but I think the nearest and most detailed suggestion was that proposed by Kyle Hailey, ex-Oracle and now working Embarcadero. There were one or two problems with the original email which I've fixed up here ...

For the wait event class I was teaching I wanted to show an example of taking ASH data and finding the blocking statement in the log miner data, but found this was less than reliable. Sometimes it would work sometimes it didn't. Not sure what the issue was. I think dumping the redo log itself would be more dependable. I think logminer might not report everything - ie I think there is some filtering going on.

Anyway here are some steps that might be of use to people. I get  XID but you probably don't need it, but I recall the XID being useful in doing the redo log dumps

Setup

SYS@TEST1020> set lines 120
SYS@TEST1020> column member format a60
SYS@TEST1020>
SYS@TEST1020> alter system switch logfile;

System altered.

SYS@TEST1020> select group#, thread#, status from v$log;

    GROUP#    THREAD# STATUS
---------- ---------- ----------------
         1          1 CURRENT
         2          1 ACTIVE
         3          1 ACTIVE

SYS@TEST1020> select group#, member from v$logfile;

    GROUP# MEMBER
---------- ------------------------------------------------------------
         1 C:\ORACLE\PRODUCT\10.2.0\ORADATA\TEST1020\REDO01.LOG
         2 C:\ORACLE\PRODUCT\10.2.0\ORADATA\TEST1020\REDO02.LOG
         3 C:\ORACLE\PRODUCT\10.2.0\ORADATA\TEST1020\REDO03.LOG

SYS@TEST1020> exec dbms_logmnr.add_logfile('&&my_member');
Enter value for my_member: C:\ORACLE\PRODUCT\10.2.0\ORADATA\TEST1020\REDO01.LOG

PL/SQL procedure successfully completed.

SYS@TEST1020> exec dbms_logmnr.start_logmnr(options => dbms_logmnr.dict_from_online_catalog);

PL/SQL procedure successfully completed.

Test Case

Session 1

TESTUSER@TEST1020> create table test_tab1
                      as select object_id pk_id, object_name from all_objects;

Table created.

TESTUSER@TEST1020> select rowid, object_name from test_tab1 where pk_id=313;

ROWID              OBJECT_NAME
------------------ ------------------------------
AAAN2NAAKAAAaBLAEX SYSTEM_PRIVILEGE_MAP

TESTUSER@TEST1020> update test_tab1 set object_name='SESSION 1' where pk_id=313;

1 row updated.

Session 2

TESTUSER@TEST1020> update test_tab1 set object_name='SESSION 2' where pk_id=313;

So Session 1 is now blocking session 2 ... have a look in V$TRANSACTION

SYS@TEST1020> select start_time, xid, xidusn, xidslot, xidsqn, start_scn, 
              to_char(start_scn, 'XXXXXXXXXX') 
              from v$transaction order by start_time;

START_TIME           XID                  XIDUSN    XIDSLOT     XIDSQN  START_SCN TO_CHAR(STA
-------------------- ---------------- ---------- ---------- ---------- ---------- -----------
04/20/09 20:46:39    0A00240064180000         10         36       6244          0           0

Commit Session 1

TESTUSER@TEST1020> commit;

Commit complete.

... so that Session 2 is released.

1 row updated.

and take a look in V$TRANSACTION at the new transaction details

SYS@TEST1020> select start_time, xid, xidusn, xidslot, xidsqn, start_scn, to_cha
r(start_scn, 'XXXXXXXXXX') from v$transaction order by start_time;

START_TIME           XID                  XIDUSN    XIDSLOT     XIDSQN  START_SCN TO_CHAR(STA
-------------------- ---------------- ---------- ---------- ---------- ---------- -----------
04/20/09 20:46:54    08002000681F0000          8         32       8040    9061094      8A42E6

So the blocking lock problem has now cleared. Let's start gathering information to see if we can identify the problem.

Analysis

Parameters for 'enq: TX - Row Lock Contention'
    P2=usn<<16||slot
    P3=Sequence
     =>  XID

Let's find our WAITER and the BLOCKING XID

SYS@TEST1020> select * from
  2     (select lpad(ltrim(to_char(p2,'XXXXXX')),6,'0')||
  3             '00'||
  4             ltrim(to_char(mod(p3,256),'XX'))||
  5             ltrim(to_char(trunc(p3/256),'XX'))||
  6             '0000' block_xid,
  7             to_char(p2,'XXXXXXXX') p2hex,
  8             to_char(p3,'XXXXXXXX') p3hex,
  9             trunc(p2/65536) usn,
 10             mod(p2,65536) slot,
 11             p3 sqn, xid wait_xid
 12     from v$active_session_history
 13     where event like 'enq: T%'
 14     order by sample_time desc) where rownum < 2;

BLOCK_XID          P2HEX     P3HEX            USN       SLOT        SQN WAIT_XID

------------------ --------- --------- ---------- ---------- ---------- --------
0A00240064180000       A0024      1864         10         36       6244

Now let's use logminer to find out what the BLOCKING SQL was

SYS@TEST1020> select username, session# sid, serial# , sql_redo from v$logmnr_co
ntents where  XID = '&&blocking_xid'
  2  /
Enter value for blocking_xid: 0A00240064180000
old   1: select username, session# sid, serial# , sql_redo from v$logmnr_content
s where  XID = '&&blocking_xid'
new   1: select username, session# sid, serial# , sql_redo from v$logmnr_content
s where  XID = '0A00240064180000'

USERNAME                              SID    SERIAL#
------------------------------ ---------- ----------
SQL_REDO
--------------------------------------------------------------------------------
UNKNOWN                                 0          0
commit;

Oh

Well, how about trying a different approach?

SYS@TEST1020> select distinct xid , xidusn, xidslt, xidsqn, username, session# s
id, serial# , sql_redo
  2  from v$logmnr_contents
  3  where timestamp > sysdate- &minutes/(60*24)
  4  and xidusn=10
  5  and xidslt=36;
Enter value for minutes: 10
old   3: where timestamp > sysdate- &minutes/(60*24)
new   3: where timestamp > sysdate- 10/(60*24)

XID                  XIDUSN     XIDSLT     XIDSQN USERNAME
        SID    SERIAL#
---------------- ---------- ---------- ---------- ------------------------------
 ---------- ----------
SQL_REDO
--------------------------------------------------------------------------------
----------------------------------------
0A00240064180000         10         36       6244 UNKNOWN
          0          0
commit;

Which isn't too helpful - I can't see any information about Session 1's row update. If anyone has any ideas why, I'm all ears.

In the next post I'll look at a redo log file dump to see if that has any more information.