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.

7 Comments

  1. Amardeep Sidhu's Gravatar Amardeep Sidhu
    March 12, 2012    

    Cool Stuff !

    Thanks !

  2. March 14, 2012    

    Hey Christian,
    many ways are leading to Rome :-))

    As far as i can see you have worked with v$session – this means that the both session were still running while you have done your analysis.
    I would prefer the “oradebug dump errorstack” way, because of handling large redo / archive log files with log miner can be some cruel story sometimes.

    http://oracle-study-notes.blogspot.com/2009/05/oradebug-dump-errorstack-and-bind.html

    Best Regards
    Stefan

    • March 14, 2012    

      Hi Stefan

      Yeap, it’s not the only way to do something like that. That said, two comments:
      - if I can, I prefer to avoid running ORADEBUG on a production system
      - the technique described in the post you referenced can only be used for the blocker when the cursor is still open (in general this is not the case…)

      Cheers,
      Chris

  3. Vaibhav's Gravatar Vaibhav
    March 14, 2012    

    Thank you for sharing the analysis. It is very useful.

  4. March 15, 2012    

    Hi,

    thanks Christian, great stuff. Is log mining something that is safe to do on a live production database?

    Best regards,
    Nikolay

    • March 15, 2012    

      Hi Nikolay

      I’m not aware of specific problems in doing it.

      HTH
      Chris

  5. May 17, 2012    

    HI, thanks nice post.
    Logminer is very nice tool for analyzing oracle redo logs and archived redo logs.

    I created a video about Logminer. Please watch : http://www.youtube.com/watch?feature=player_embedded&v=-3Ei1qJZiXE

  1. Log Buffer #263, A Carnival of the Vanities for DBAs | The Pythian Blog on March 16, 2012 at 07:02
  2. Log Buffer #263, A Carnival of the Vanities for DBAs on February 13, 2013 at 17:01

Leave a Reply

Your email address will not be published. Required fields are marked *