Diagnosing Locking Problems using ASH/LogMiner ...

This time, instead of dumping the contents of the log file for a specific Data Block Address (DBA), as in the last part, I’m going to dump it for a specific operation type – Lock Rows (SELECT FOR UPDATE in this case) – which is part of the Row Operations layer (11) and is the LKR operation (4). This will allow me to eliminate less interesting activity and will include information for blocks other than the specific block that contains the PK_ID=313 row.

 

SQL> alter system dump logfile '&&my_member'
  2  layer 11 opcode 4;
old   1: alter system dump logfile '&&my_member'
new   1: alter system dump logfile '/data/oradata/PPL/redo03.log'
System altered.

 

Next, a quick reminder of the transaction history from the previous tests, that this log file covers.

Transaction ID        Session 1 Activity  Transaction ID          Session 2 Activity

0003001100008615  Whole Table Locked
                            Locks Released
0002000100008DAA  Two Rows Locked
                            Locks Released
000900110000891B  PK_ID=313 Locked                               Waiting to lock PK_ID=313
                            Lock Released       00080005000081D3    PK_ID=313 Locked       

Looking at the header (line numbers added by vi), I can see that the dump is restricted to Opcode 11.4.

 

    19  DUMP OF REDO FROM FILE '/data/oradata/PPL/redo03.log'
    20   Opcode 11.4 only
    21   RBAs: 0x000000.00000000.0000 thru 0xffffffff.ffffffff.ffff
    22   SCNs: scn: 0x0000.00000000 thru scn: 0xffff.ffffffff
    23   Times: creation thru eternity

 

Next I search for ‘xid: ‘ to find the first transaction ID, which brings up the first redo record, all 2214 lines of it! Relax, I’m not going to list it all here, just focus on the first CHANGE record.

 

    50  REDO RECORD - Thread:1 RBA: 0x002304.00000002.0010 LEN: 0x45b0 VLD: 0x0d
    51  SCN: 0x0000.050dc3e9 SUBSCN:  1 04/23/2009 09:40:19
    52  CHANGE #1 TYP:0 CLS: 1 AFN:3 DBA:0x00c06125 OBJ:144543 SCN:0x0000.050dc005 SEQ:185 OP:11.4
    53  KTB Redo
    54  op: 0x01  ver: 0x01
    55  op: F  xid:  0x0003.011.00008615    uba: 0x00803aaa.0f30.01
    56  KDO Op code: LKR row dependencies Disabled
    57    xtype: XA flags: 0x00000000  bdba: 0x00c06125  hdba: 0x00c06103
    58  itli: 2  ispac: 0  maxfr: 4858
    59  tabn: 0 slot: 183 to: 2

 

I can see this is a change to a Data Block (Class 1), the Trancation ID is 0x0003.011.00008615 which matches the XID 0003001100008615 from V$TRANSACTION and that it’s a row lock operation. Next up is a 5.2 operation that starts off the new transaction)

 

    60  CHANGE #2 TYP:0 CLS:21 AFN:2 DBA:0x00800029 OBJ:4294967295 SCN:0x0000.050dc3c0 SEQ:  1 OP:5.2
    61  ktudh redo: slt: 0x0011 sqn: 0x00008615 flg: 0x000a siz: 108 fbi: 0
    62              uba: 0x00803aaa.0f30.01    pxid:  0x0000.000.00000000

 

After that you’ll see tons more 11.4 entries as the various locks are acquired. Next I’ll search for the transaction ID for the second transaction (that locked two rows) by searching for ‘xid:  0x0002’ (two spaces in that string).

 

192358  REDO RECORD - Thread:1 RBA: 0x002304.00000ce8.0010 LEN: 0x0238 VLD: 0x0d
192359  SCN: 0x0000.050dc41f SUBSCN:  1 04/23/2009 09:40:20
192360  CHANGE #1 TYP:0 CLS: 1 AFN:3 DBA:0x00c06104 OBJ:144543 SCN:0x0000.050dc411 SEQ:102 OP:11.4
192361  KTB Redo
192362  op: 0x01  ver: 0x01
192363  op: F  xid:  0x0002.001.00008daa    uba: 0x00808827.124c.31
192364  KDO Op code: LKR row dependencies Disabled
192365    xtype: XA flags: 0x00000000  bdba: 0x00c06104  hdba: 0x00c06103
192366  itli: 3  ispac: 0  maxfr: 4858
192367  tabn: 0 slot: 2 to: 3

 

Looking at the line numbers, you can probably see why I didn’t want to show you all of the REDO RECORDs for the first transaction! Checking the transaction ID, that’s the one we’re looking for. While I’m at it, I might as well track down the last two transactions by searching for their xid:

 

192447  REDO RECORD - Thread:1 RBA: 0x002304.00000cea.0010 LEN: 0x0180 VLD: 0x0d
192448  SCN: 0x0000.050dc423 SUBSCN:  1 04/23/2009 09:40:25
192449  CHANGE #1 TYP:0 CLS: 1 AFN:3 DBA:0x00c06104 OBJ:144543 SCN:0x0000.050dc41f SEQ:  4 OP:11.4
192450  KTB Redo
192451  op: 0x01  ver: 0x01
192452  op: F  xid:  0x0009.011.0000891b    uba: 0x0081e118.14ee.05
192453  KDO Op code: LKR row dependencies Disabled
192454    xtype: XA flags: 0x00000000  bdba: 0x00c06104  hdba: 0x00c06103
192455  itli: 3  ispac: 0  maxfr: 4858
192456  tabn: 0 slot: 3 to: 3
192496  REDO RECORD - Thread:1 RBA: 0x002304.00000cec.0010 LEN: 0x0180 VLD: 0x0d
192497  SCN: 0x0000.050dc428 SUBSCN:  1 04/23/2009 09:40:34
192498  CHANGE #1 TYP:0 CLS: 1 AFN:3 DBA:0x00c06104 OBJ:144543 SCN:0x0000.050dc426 SEQ:  1 OP:11.4
192499  KTB Redo
192500  op: 0x01  ver: 0x01
192501  op: F  xid:  0x0008.005.000081d3    uba: 0x0081eda9.1058.20
192502  KDO Op code: LKR row dependencies Disabled
192503    xtype: XA flags: 0x00000000  bdba: 0x00c06104  hdba: 0x00c06103
192504  itli: 3  ispac: 0  maxfr: 4858
192505  tabn: 0 slot: 3 to: 3

Yep, they both look right (which is more than can be said for Log Miner’s output!). The fact is that you could probably work out which transaction had locked the rows and the type of work it was doing, but still no nearer finding the offending SQL statement, really.

In the next and absolutely definitely last part, I'll have a brief overview of some other suggestions such as Miladin Modrakivic's.