Analysing Row Lock Contention with LogMiner

Recently I had to analyse a row lock contention problem that can be illustrated by the following test case:

• A session (let’s call it #1) creates a table and inserts a row into it (note that “n” is the primary key of the table):

SQL> CREATE TABLE t (n NUMBER PRIMARY KEY);

SQL> VARIABLE n NUMBER

SQL> execute :n := 1

SQL> INSERT INTO t VALUES (:n);

• Another session (let’s call it #2) inserts the same data into the same table:

SQL> VARIABLE n NUMBER

SQL> execute :n := 1

SQL> INSERT INTO t VALUES (:n);

• Since session #1 did not commit and that session #2 inserted a row with the same primary key, session #2 is blocked waiting for session #1 to either commit or rollback:

SQL> SELECT sid, blocking_session, event, sql_text
  2  FROM v$session LEFT OUTER JOIN v$sqlarea USING (sql_id)
  3  WHERE nvl(blocking_session,sid) IN (SELECT holding_session FROM dba_blockers);

       SID BLOCKING_SESSION EVENT                          SQL_TEXT
---------- ---------------- ------------------------------ ------------------------------
       130                  SQL*Net message from client
       197              130 enq: TX - row lock contention  INSERT INTO t VALUES (:n)

It goes without saying that in such a case the problem is the application that tried to insert two rows with the same primary key. In the real case the primary key was a natural key, not a surrogate key generated through a sequence. To help the developers troubleshoot the problem it was therefore necessary to know the actual value of the bind variable used for the two inserts. Unfortunately this information is stored in the PGA of the server processes and, therefore, it is not directly accessible. In addition I started investigating the problem only a couple of hours after the contention began and, therefore, also a view like V$SQL_BIND_CAPTURE is of no use.

As a result I decided to mine the archived redo logs to find the information I was looking for. Here is what I did:

• Find out the XID of the transaction holding the row lock:

SQL> SELECT t.xidusn, t.xidslot, t.xidsqn, t.start_time, t.start_scn
  2  FROM v$transaction t JOIN v$session s ON t.addr = s.taddr
  3  WHERE s.sid = 130;

    XIDUSN    XIDSLOT     XIDSQN START_TIME            START_SCN
---------- ---------- ---------- -------------------- ----------
         7         12       1049 03/09/12 07:10:25       1462388

• Find out which archived redo log contains the first redo records of that transaction:

SQL> SELECT name
  2  FROM v$archived_log
  3  WHERE 1462388 BETWEEN first_change# AND next_change# - 1;

NAME
-----------------------------------------------------------------------------------------------
/u00/app/oracle/fast_recovery_area/DBA112/archivelog/2012_03_09/o1_mf_1_94_7om7qzdx_.arc

• Start LogMiner:

SQL> EXECUTE dbms_logmnr.add_logfile(logfilename=>'/u00/app/oracle/fast_recovery_area/DBA112/archivelog/2012_03_09/o1_mf_1_94_7om7qzdx_.arc')

SQL> EXECUTE dbms_logmnr.start_logmnr(options=>dbms_logmnr.dict_from_online_catalog)

• Extract the redo information of the operations performed by the transaction holding the row lock and, therefore, finding that the value of the bind variable was “1”:

SQL> SELECT sql_redo
  2  FROM v$logmnr_contents
  3  WHERE xidusn = 7
  4  AND xidslt = 12
  5  AND xidsqn = 1049;

SQL_REDO
--------------------------------------------------------------------------------
set transaction read write;
insert into "CHRIS"."T"("N") values ('1');

• Stop LogMiner

SQL> EXECUTE dbms_logmnr.end_logmnr

In conclusion, even though mining (archived) redo logs for extracting the value of bind variables is probably not the most typical use of LogMiner, it works well. Therefore, do not forget this possibility if you have to do it.