Diagnosing Locking Problems using ASH/LogMiner ...

So what about those SELECT FOR UPDATEs?

I know that they’ll generate redo entries and so something should appear in both log file dumps and the LogMiner output, but what exactly will appear? (This is all on Oracle 10.2.0.4)

For this post I’ll go back to the example from Part 4, where Session 1 performs three different SELECT FOR UPDATE statements against the same table, TEST_TAB1, and rolls the first two back before leaving the third as the statement that’s blocking Session 2. i.e. Three possible guilty parties in very quick succession, which makes the exact source harder to find. This time, I granted select privileges on V$TRANSACTION to TESTUSER, so that we could take a quick peek at the contents after each SELECT FOR UPDATE. I've also set up LogMiner access in the SYS session, as in the last couple of posts.

Session 1 – Connected as TESTUSER

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

Trimmed ...
       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> select start_time, xid, xidusn, xidslot,
  2          xidsqn, start_scn, to_char(start_scn, 'XXXXXXXXXX')
  3  from v$transaction
  4  order by start_time;

START_TIME           XID              XIDUSN XIDSLOT  XIDSQN  START_SCN TO_CHAR(STA
-------------------- ---------------- ------ ------- ------- ---------- -----------
04/23/09 09:40:16    0003001100008615      3      17   34325          0           0

SQL> rollback

Rollback complete.

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

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

SQL> select start_time, xid, xidusn, xidslot,
  2          xidsqn, start_scn, to_char(start_scn, 'XXXXXXXXXX')
  3  from v$transaction
  4  order by start_time;

START_TIME           XID              XIDUSN XIDSLOT  XIDSQN  START_SCN TO_CHAR(STA
-------------------- ---------------- ------ ------- ------- ---------- -----------
04/23/09 09:40:20    0002000100008DAA      2       1   36266   84788253     50DC41D

SQL> rollback;

Rollback complete.

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

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

SQL> select start_time, xid, xidusn, xidslot,
  2          xidsqn, start_scn, to_char(start_scn, 'XXXXXXXXXX')
  3  from v$transaction
  4  order by start_time;

START_TIME           XID              XIDUSN XIDSLOT  XIDSQN  START_SCN TO_CHAR(STA
-------------------- ---------------- ------ ------- ------- ---------- -----------
04/23/09 09:40:20    000900110000891B      9      17   35099   84788256     50DC420

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 PK_ID=313 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.

The lock is released and Session 2 acquires the lock and then releases it.

Session 2 - Connected as TESTUSER

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

SQL> select start_time, xid, xidusn, xidslot,
  2          xidsqn, start_scn, to_char(start_scn, 'XXXXXXXXXX')
  3  from v$transaction
  4  order by start_time;

START_TIME           XID              XIDUSN XIDSLOT  XIDSQN  START_SCN TO_CHAR(STA
-------------------- ---------------- ------ ------- ------- ---------- -----------
04/23/09 09:40:22    00080005000081D3      8       5   33235   84788259     50DC423

SQL> rollback;

Rollback complete.

Taken as a whole, the time-line looks like this

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               
OK, let’s see what LogMiner makes of this. First, let’s look for any entries associated with the specific transaction that was the blocker.

SQL> select username,session# sid,serial#,sql_redo from v$logmnr_contents 
     where XID = '&&blocking_xid';
Enter value for blocking_xid: 000900110000891B
old   1: select username,session# sid,serial#,sql_redo from v$logmnr_contents 
         where XID = '&&blocking_xid'
new   1: select username,session# sid,serial#,sql_redo from v$logmnr_contents 
         where XID = '000900110000891B'

USERNAME                              SID    SERIAL#
------------------------------ ---------- ----------
SQL_REDO
-----------------------------------------------------------------------------------------
                                        0          0
rollback;

Mmmm … ‘rollback’. Not too helpful, is it? Maybe if I look at the undo segment and slot from another of Kyle's queries?

SQL> select distinct xid , xidusn, xidslt, xidsqn, 
     username, session# sid, serial# , sql_redo
  2  from v$logmnr_contents
  3  where timestamp > sysdate- &minutes/(60*24)
  4  and xidusn=&my_usn
  5  and xidslt=&my_slot;
Enter value for minutes: 5
old   3: where timestamp > sysdate- &minutes/(60*24)
new   3: where timestamp > sysdate- 5/(60*24)
Enter value for my_usn: 9
old   4: and xidusn=&my_usn
new   4: and xidusn=9
Enter value for my_slot: 17
old   5: and xidslt=&my_slot
new   5: and xidslt=17
XID                  XIDUSN     XIDSLT     XIDSQN USERNAME                   SID    SERIAL#
---------------- ---------- ---------- ---------- ------------------- ---------- ----------
SQL_REDO
---------------------------------------------------------------------------------
000900110000891B          9         17      35099                              0          0
rollback;
00090011FFFFFFFF          9         17 4294967295                              0          0
Unsupported

Now that's a bit interesting because I think we'll find that 'Unsupported' operation is the third SELECT FOR UPDATE (which blocks Session 2) but the Transaction ID looks wrong. Oh, and why is the SQL_REDO 'Unsupported'? Well, would you really want to redo a SELECT FOR UPDATE that merely locks rows?

Next I’ll try displaying all operations against TEST_TAB1 in the past 5 minutes. I’ll group the results so we only see the discrete actions and how many entries there are for each.

 

SQL> select xid, xidusn, xidslt, xidsqn, session#, serial#, sql_redo, count(*)
  2  from v$logmnr_contents
  3  where timestamp > sysdate- &minutes/(60*24)
  4  and table_name='TEST_TAB1'
  5* group by xid, xidusn, xidslt, xidsqn, session#, serial#, sql_redo
Enter value for minutes: 60
old   3: where timestamp > sysdate- &minutes/(60*24)
new   3: where timestamp > sysdate- 60/(60*24)

XID                XIDUSN   XIDSLT     XIDSQN   SESSION#    SERIAL# SQL_REDO      COUNT(*)
---------------- -------- -------- ---------- ---------- ---------- ----------- ----------
00080005FFFFFFFF        8        5 4294967295          0          0 Unsupported          1
0003001100008615        3       17      34325          0          0 Unsupported       8858
00020001FFFFFFFF        2        1 4294967295          0          0 Unsupported          2
00090011FFFFFFFF        9       17 4294967295          0          0 Unsupported          1

Good - that's starting to look more like it. I can see all 4 discrete SELECT FOR UPDATE transactions from the test (the rollback operation returned by the previous query isn't necessarily specific to TEST_TAB1 so I'm not surprised it doesn't appear). The XIDs still look a little screwy and you're trusting me at this stage that these are SELECT FOR UPDATEs. Notice the number of entries for the different transactions - two single row updates, one 2 row update and a multiple row update.

However, the transaction IDs for three of the transactions have the wrong sequence number of FFFFFFFF and even this output is the best I've seen. I've run this several times and sometimes it's captured by LogMiner, sometime it isn't. I appreciate that's a little vague, but I have very little confidence in some of the results I've seen on different tests.

I dumped the log file for this example, so I'll look at that in the next part.

Believe me when I say I'm aware of how far I've strayed from identifying the blocking SQL statement (you won't be getting that from redo entries) but I suppose I might as well carry on for one more post, maybe two.