Enqueue Experimentations

December 6, 2009

Over the years I have participated in several discussions about enqueue waits.  Below are some of those discussions.

http://forums.oracle.com/forums/thread.jspa?threadID=638246
ENQ: TX – ROW LOCK CONTENTION – this is a row level lock caused by a possible primary key or unique index violation if the first session commits its current transaction. A second session attempting to insert the value that will result in the primary key violation will sit in this wait event until the first session commits or rolls back.

Problems with initrans would show up as ENQ: TX – ALLOCATE ITL ENTRY waits in 10g/11g. But, such problems should be rare with tablespaces using ASSM.

After fixing the formatting of the top 5 wait events (total duration unknown):

EVENT                        TOTAL_WAITS  TIME_WAITED   AVG_MS PERCENT
----------------------------------------------------------------------
CPU                                         94,623.39             48
enq: TX - row lock contention     12,531    36,607.28  2921.34    18
control file parallel write    1,300,731    30,880.79    23.74    16
log file parallel write        1,510,503    12,640.80     8.37     6
log file sync                  1,072,553     9,680.07     9.03     5

12,531 * 3 second time out = 37,593 seconds = 10.44 hours.

What if the reason for the 3 second average wait time is due to a timeout. I performed a little experiment… I changed a row in a test table and then made a pot of coffee.

In session 1:

CREATE TABLE T1 (
  C1 NUMBER(10),
  C2 NUMBER(10),
  PRIMARY KEY (C1));

INSERT INTO T1
SELECT
  ROWNUM,
  ROWNUM*10
FROM
  DUAL
CONNECT BY
  LEVEL<=1000000;

COMMIT;

I now have a test table with 1,000,000 rows. I start monitoring the changes in the wait events roughly every 60 seconds, and V$SESSION_WAIT and V$LOCK roughly 4 times per second.

Back in session 1:

UPDATE
  T1
SET
  C1=-C1
WHERE
  C1<=100;

I have now modified the first 100 rows that were inserted into the table, time to make the pot of coffee.

In session 2, I try to insert a row with a primary key value of -10:

INSERT INTO T1 VALUES (
  -10,
  10);

Session 2 hangs.

If I take the third 60 second snap of the system wide wait events as the zero point, and the 11th snap as the end point. There were 149 waits on ENQ: TX – ROW LOCK CONTENTION, 148 time outs, 446.62 seconds of total time in the wait event, with an average wait time of 2.997450 seconds.

Rolling down to the session level wait events, SID 208 (my session 2) had 149 waits on ENQ: TX – ROW LOCK CONTENTION, for a total time of 446.61 seconds with an average wait time of 2.997383 seconds. All of the 149 waits and the wait time was in this one session that was locked up for the full duration of this time period because session 1 was making a pot of coffee.

Rolling down to V$SESSION_WAIT (sampled roughly 4 times per second): At the start of the third time interval, SID 208 has been in the ENQ: TX – ROW LOCK CONTENTION wait event for 39 seconds and is actively waiting trying to execute SQL with a hash value of 1001532423, the wait object is -1, wait file is 0, wait block is 0, wait row is 0, P1 is 1415053316, P2 is 196646, P3 is 4754.
At the end of the 11th time interval: , SID 208 has been in the ENQ: TX – ROW LOCK CONTENTION wait event for 483 seconds and is actively waiting trying to execute SQL with a hash value of 1001532423, the wait object is -1, wait file is 0, wait block is 0, wait row is 0, P1 is 1415053316, P2 is 196646, P3 is 4754.

Rolling down to V$LOCK (sampled roughly 4 times per second): I see that SID 214 (session 1) is blocking SID 208 (session 2). SID 214 has a TX lock in mode 6 with ID1 of 196646 and ID2 of 4754. SID 208 is requesting a TX lock in mode 4 with ID1 of 196646 and ID2 of 4754.

So, it seems that I need a faster coffee pot rather than an additional index on my table. It could be that the above process would have found that the application associated with SID 214 was abandoned or crashed and for some reason the lock was not released for a long period of time, a little less than 10.44 hours in your case.

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

http://forums.oracle.com/forums/thread.jspa?threadID=860488
TYPE=TX, LMODE=6, REQUEST=6 = session 2 is attempting to update a row that is locked by session 1’s transaction (likely session 1 already updated the row)
TYPE=TX, LMODE=6, REQUEST=4 = session 2 is attempting to insert a row with the same primary key value or unique index value as a row just inserted by session 1
TYPE=TX, LMODE=6, REQUEST=4 = ITL Problem or bitmap index fragment problem
RBS Seg # = trunc(p2/65536) = v$transaction.xidusn
RBS Slot # = bitand( p2, 65535) = v$transaction.xidslot
P3 = v$transaction.xidsqn

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

http://forums.oracle.com/forums/thread.jspa?messageID=2613515

Let’s try a couple experiments to see if we can reproduce what you are seeing (this may not be the only possible cause):

#Basic Setup
Session 1:

CREATE TABLE T1 (
  C1 VARCHAR2(10),
  C2 NUMBER(12),
  PRIMARY KEY (C1));

Table created.

INSERT INTO
  T1
VALUES(
  'ONE',
  1);

1 row created.

INSERT INTO
  T1
VALUES(
  'TWO',
  2);

1 row created.
SELECT DISTINCT
  SID
FROM
  V$MYSTAT;

       SID
----------
       150

#Test 1 (Primary Key Violation, No Commit)
Session 2:

SELECT DISTINCT
  SID
FROM
  V$MYSTAT;

       SID
----------
       143

INSERT INTO
  T1
VALUES(
  'TWO',
  2);

(Session 2 Hung)
In Session 1:

SELECT
  S.SID,
  S.PROGRAM,
  S.STATUS,
  SW.EVENT,
  SW.WAIT_TIME,
  SW.STATE,
  SW.SECONDS_IN_WAIT,
  S.SQL_ADDRESS,
  S.SQL_HASH_VALUE,
  S.ROW_WAIT_OBJ#,
  S.ROW_WAIT_FILE#,
  S.ROW_WAIT_BLOCK#,
  S.ROW_WAIT_ROW#,
  SW.P1 ,
  SW.P2,
  SW.P3
FROM
  V$SESSION S,
  V$SESSION_WAIT SW
WHERE 
  S.USERNAME IS NOT NULL
  AND SW.SID=S.SID
  AND SW.EVENT NOT LIKE '%SQL*Net%'
  AND SW.EVENT NOT IN ('Streams AQ: waiting for messages in the queue','wait for unread message on broadcast channel');

       SID PROGRAM       STATUS   EVENT                          WAIT_TIME STATE     SECONDS_IN_WAIT SQL_ADDR SQL_HASH_VALUE ROW_WAIT_OBJ# ROW_WAIT_FILE# ROW_WAIT_BLOCK# ROW_WAIT_ROW#         P1         P2         P3
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
       143 sqlplus.exe   ACTIVE   enq: TX - row lock contention          0 WAITING               424 1CA703CC     2983910641            -1              0               0             0 1415053316     393235      11543

 

SELECT
  S.SID,
  S.PROGRAM,
  S.SQL_HASH_VALUE,
  L.REQUEST,
  L.ID1,
  L.ID2,
  L.LMODE,
  L.TYPE,
  L.BLOCK
FROM
  V$LOCK L,
  V$SESSION S
WHERE
  (L.ID1, L.ID2, L.TYPE) IN
  (SELECT
    ID1,
    ID2,
    TYPE
  FROM
    V$LOCK
  WHERE
    REQUEST > 0)
  AND L.SID=S.SID;

       SID PROGRAM     SQL_HASH_VALUE    REQUEST        ID1        ID2      LMODE TY      BLOCK
-----------------------------------------------------------------------------------------------
       143 sqlplus.exe     2983910641          4     393235      11543          0 TX          0
       150 sqlplus.exe      883681740          0     393235      11543          6 TX          1

#Test 1 missed the mark, no ROW_WAIT_OBJ#

COMMIT;

In Session 2:

ERROR at line 1:
ORA-00001: unique constraint (TESTUSER.SYS_C0014294) violated

#Test 2 (Primary Key Updated, No Commit)
In Session 1:

UPDATE
  T1
SET
  C1=C1
WHERE
  C1='TWO';

1 row updated.

In Session 2:

UPDATE
  T1
SET
  C1=C1
WHERE
  C1='TWO';

In Session 1:

SELECT
  S.SID,
  S.PROGRAM,
  S.STATUS,
  SW.EVENT,
  SW.WAIT_TIME,
  SW.STATE,
  SW.SECONDS_IN_WAIT,
  S.SQL_ADDRESS,
  S.SQL_HASH_VALUE,
  S.ROW_WAIT_OBJ#,
  S.ROW_WAIT_FILE#,
  S.ROW_WAIT_BLOCK#,
  S.ROW_WAIT_ROW#,
  SW.P1 ,
  SW.P2,
  SW.P3
FROM
  V$SESSION S,
  V$SESSION_WAIT SW
WHERE 
  S.USERNAME IS NOT NULL
  AND SW.SID=S.SID
  AND SW.EVENT NOT LIKE '%SQL*Net%'
  AND SW.EVENT NOT IN ('Streams AQ: waiting for messages in the queue','wait for unread message on broadcast channel');

       SID PROGRAM       STATUS   EVENT                          WAIT_TIME STATE     SECONDS_IN_WAIT SQL_ADDR SQL_HASH_VALUE ROW_WAIT_OBJ# ROW_WAIT_FILE# ROW_WAIT_BLOCK# ROW_WAIT_ROW#         P1         P2         P3
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
       143 sqlplus.exe   ACTIVE   enq: TX - row lock contention           0 WAITING               38 222799C4     1367536044         73419              1           84362             1 1415053318     589828      11227

 

SELECT
  S.SID,
  S.PROGRAM,
  S.SQL_HASH_VALUE,
  L.REQUEST,
  L.ID1,
  L.ID2,
  L.LMODE,
  L.TYPE,
  L.BLOCK
FROM
  V$LOCK L,
  V$SESSION S
WHERE
  (L.ID1, L.ID2, L.TYPE) IN
  (SELECT
    ID1,
    ID2,
    TYPE
  FROM
    V$LOCK
  WHERE
    REQUEST > 0)
  AND L.SID=S.SID;

       SID PROGRAM     SQL_HASH_VALUE    REQUEST        ID1        ID2      LMODE TY      BLOCK
-----------------------------------------------------------------------------------------------
       143 sqlplus.exe     1367536044          6     589828      11227          0 TX          0
       150 sqlplus.exe      883681740          0     589828      11227          6 TX          1

#Test 2 missed the mark, ROW_WAIT_OBJ# exists and ROW_WAIT_ROW# exists

COMMIT;

In Session 2:

COMMIT;

#Test 3 (Unique Index Violation) 
In Session 1:

CREATE UNIQUE INDEX IND_T1 ON T1(C2);

Index created.

INSERT INTO
  T1
VALUES(
  'THREE',
  3);

1 row created.

In Session 2:

INSERT INTO
  T1
VALUES(
  'FOUR',
  3);

(Session 2 Hung)
In Session 1:

SELECT
  S.SID,
  S.PROGRAM,
  S.STATUS,
  SW.EVENT,
  SW.WAIT_TIME,
  SW.STATE,
  SW.SECONDS_IN_WAIT,
  S.SQL_ADDRESS,
  S.SQL_HASH_VALUE,
  S.ROW_WAIT_OBJ#,
  S.ROW_WAIT_FILE#,
  S.ROW_WAIT_BLOCK#,
  S.ROW_WAIT_ROW#,
  SW.P1 ,
  SW.P2,
  SW.P3
FROM
  V$SESSION S,
  V$SESSION_WAIT SW
WHERE 
  S.USERNAME IS NOT NULL
  AND SW.SID=S.SID
  AND SW.EVENT NOT LIKE '%SQL*Net%'
  AND SW.EVENT NOT IN ('Streams AQ: waiting for messages in the queue','wait for unread message on broadcast channel');

       SID PROGRAM       STATUS   EVENT                          WAIT_TIME STATE    SECONDS_IN_WAIT SQL_ADDR SQL_HASH_VALUE ROW_WAIT_OBJ# ROW_WAIT_FILE# ROW_WAIT_BLOCK# ROW_WAIT_ROW#         P1         P2         P3
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
       143 sqlplus.exe   ACTIVE   enq: TX - row lock contention          0 WAITING               41 1C8F8B60      463727853            -1              1           84362             1 1415053316     393242      11541

 

SELECT
  S.SID,
  S.PROGRAM,
  S.SQL_HASH_VALUE,
  L.REQUEST,
  L.ID1,
  L.ID2,
  L.LMODE,
  L.TYPE,
  L.BLOCK
FROM
  V$LOCK L,
  V$SESSION S
WHERE
  (L.ID1, L.ID2, L.TYPE) IN
  (SELECT
    ID1,
    ID2,
    TYPE
  FROM
    V$LOCK
  WHERE
    REQUEST > 0)
  AND L.SID=S.SID;

       SID PROGRAM     SQL_HASH_VALUE    REQUEST        ID1        ID2      LMODE TY      BLOCK
-----------------------------------------------------------------------------------------------
       143 sqlplus.exe      463727853          4     393242      11541          0 TX          0
       150 sqlplus.exe      883681740          0     393242      11541          6 TX          1

#Test 3 missed the mark, no ROW_WAIT_OBJ#
In Session 1:

COMMIT;

Commit complete.

In Session 2:

ERROR at line 1:
ORA-00001: unique constraint (TESTUSER.IND_T1) violated

#Test 4 (Unique Index Violation)
In Session 1:

UPDATE
  T1
SET
  C2=C2+1
WHERE
  C2=3;

1 row updated.

In Session 2:

INSERT INTO
  T1
VALUES(
  'FOUR',
  3);

(Session 2 Hung)
In Session 1:

SELECT
  S.SID,
  S.PROGRAM,
  S.STATUS,
  SW.EVENT,
  SW.WAIT_TIME,
  SW.STATE,
  SW.SECONDS_IN_WAIT,
  S.SQL_ADDRESS,
  S.SQL_HASH_VALUE,
  S.ROW_WAIT_OBJ#,
  S.ROW_WAIT_FILE#,
  S.ROW_WAIT_BLOCK#,
  S.ROW_WAIT_ROW#,
  SW.P1 ,
  SW.P2,
  SW.P3
FROM
  V$SESSION S,
  V$SESSION_WAIT SW
WHERE 
  S.USERNAME IS NOT NULL
  AND SW.SID=S.SID
  AND SW.EVENT NOT LIKE '%SQL*Net%'
  AND SW.EVENT NOT IN ('Streams AQ: waiting for messages in the queue','wait for unread message on broadcast channel');

       SID PROGRAM       STATUS   EVENT                          WAIT_TIME STATE    SECONDS_IN_WAIT SQL_ADDR SQL_HASH_VALUE ROW_WAIT_OBJ# ROW_WAIT_FILE# ROW_WAIT_BLOCK# ROW_WAIT_ROW#         P1         P2         P3
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
       143 sqlplus.exe   ACTIVE   enq: TX - row lock contention          0 WAITING               18 1C8F8B60      463727853            -1              1           84362             1 1415053316      65560       8736

 

SELECT
  S.SID,
  S.PROGRAM,
  S.SQL_HASH_VALUE,
  L.REQUEST,
  L.ID1,
  L.ID2,
  L.LMODE,
  L.TYPE,
  L.BLOCK
FROM
  V$LOCK L,
  V$SESSION S
WHERE
  (L.ID1, L.ID2, L.TYPE) IN
  (SELECT
    ID1,
    ID2,
    TYPE
  FROM
    V$LOCK
  WHERE
    REQUEST > 0)
  AND L.SID=S.SID;

       SID PROGRAM     SQL_HASH_VALUE    REQUEST        ID1        ID2      LMODE TY      BLOCK
-----------------------------------------------------------------------------------------------
       143 sqlplus.exe      463727853          4      65560       8736          0 TX          0
       150 sqlplus.exe      883681740          0      65560       8736          6 TX          1

#Test 4 missed the mark, ROW_WAIT_OBJ# does not exist and ROW_WAIT_ROW# exists

ROLLBACK;

In Session 2:

ROLLBACK;

#Test 5 (Select For Update in Two Sessions)
In Session 1:

SELECT
  *
FROM
  T1
FOR UPDATE;

C1                 C2
---------------------
ONE                 1
TWO                 2
THREE               3

In Session 1:

SELECT
  *
FROM
  T1
FOR UPDATE;

(Session 2 Hung)
In Session 1:

SELECT
  S.SID,
  S.PROGRAM,
  S.STATUS,
  SW.EVENT,
  SW.WAIT_TIME,
  SW.STATE,
  SW.SECONDS_IN_WAIT,
  S.SQL_ADDRESS,
  S.SQL_HASH_VALUE,
  S.ROW_WAIT_OBJ#,
  S.ROW_WAIT_FILE#,
  S.ROW_WAIT_BLOCK#,
  S.ROW_WAIT_ROW#,
  SW.P1 ,
  SW.P2,
  SW.P3
FROM
  V$SESSION S,
  V$SESSION_WAIT SW
WHERE 
  S.USERNAME IS NOT NULL
  AND SW.SID=S.SID
  AND SW.EVENT NOT LIKE '%SQL*Net%'
  AND SW.EVENT NOT IN ('Streams AQ: waiting for messages in the queue','wait for unread message on broadcast channel');

       SID PROGRAM       STATUS   EVENT                          WAIT_TIME STATE    SECONDS_IN_WAIT SQL_ADDR SQL_HASH_VALUE ROW_WAIT_OBJ# ROW_WAIT_FILE# ROW_WAIT_BLOCK# ROW_WAIT_ROW#         P1         P2         P3
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
       143 sqlplus.exe   ACTIVE   enq: TX - row lock contention          0 WAITING               18 1C911EE4     3199333328         73419              1           84362             0 1415053318     327707      11953

 

SELECT
  S.SID,
  S.PROGRAM,
  S.SQL_HASH_VALUE,
  L.REQUEST,
  L.ID1,
  L.ID2,
  L.LMODE,
  L.TYPE,
  L.BLOCK
FROM
  V$LOCK L,
  V$SESSION S
WHERE
  (L.ID1, L.ID2, L.TYPE) IN
  (SELECT
    ID1,
    ID2,
    TYPE
  FROM
    V$LOCK
  WHERE
    REQUEST > 0)
  AND L.SID=S.SID;

       SID PROGRAM     SQL_HASH_VALUE    REQUEST        ID1        ID2      LMODE TY      BLOCK
-----------------------------------------------------------------------------------------------
       143 sqlplus.exe     3199333328          6     327707      11953          0 TX          0
       150 sqlplus.exe      883681740          0     327707      11953          6 TX          1

#Test 5 ROW_WAIT_OBJ# exist and ROW_WAIT_ROW# does not exists, lock request mode is 6 and the other session is holding the lock in mode 6.  It looks like one possibility was found.

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

http://forums.oracle.com/forums/thread.jspa?messageID=3188695
Based on a calculation it appears that the Statspack duration is about 20 minutes (this is likely reasonable). I did not spend a lot of time analyzing the information that you posted, so a quick summary of what I see that looks interesting:

                                                                  Avg
                                                     Total Wait   wait    Waits
Event                               Waits   Timeouts  Time (s)    (ms)     /txn
---------------------------- ------------ ---------- ---------- ------ --------
enqueue                                83         58        208   2509      0.1
resmgr:waiting in end wait            265          0         25     94      0.4
log file parallel write             1,939          0         22     11      3.2
resmgr:waiting in check                 8          0         17   2112      0.0

 

In the above, notice that there are 58 time outs for the enqueue. The timeout period for an enqueue is 3 seconds, which means that you potentially had a single wait that lasted 58*3 (+ up to 2.99) seconds, which totals 174 (+ up to 2.99) seconds. To make the calculation simple, assume that this was a single wait lasting exactly 174 seconds. The remaining 47 seconds of the wait divided by 25 (83-58) means that the remaining average wait time is 1.88 seconds. With Oracle 9.0.1 it is more difficult to see how much time was spent in each of the different types of enqueues compared to Oracle 10g and above.

Looking at the enqueue information that you posted:

                                                       Avg Wt        Wait
Eq     Requests    Succ Gets Failed Gets       Waits  Time (ms)    Time (s)
-- ------------ ------------ ----------- ----------- ----------- ------------
TX          569          568           0          30    7,356.07          221

 

It appears that all of the enqueue activity is of the type TX, while are row level enqueues – usually meaning that someone updated a row, and there was a pause between the time that the update was performed and a commit or rollback was executed. There are multiple causes for TX enqueues which may not be found with a Statspack report. From my notes (possibly based on the Oracle Performance Tuning Guide):
* TX enqueues are acquired exclusive when a transaction initiates its first change and held until the transaction COMMITs or ROLLBACK.
* Waits for TX in mode 6 occurs when a session is waiting for a row level lock that is already held by another session. The wait event for mode 6 TX enqueues is ‘enq: TX – row lock contention’ on 10g and above.
* Waits for TX in mode 4 can occur when a session wants to lock a row in the block, but one or more other sessions have rows locked in the same block and there is no free Interested Transaction LIST slot in the block. Oracle will usually dynamically add another ITL slot if there is sufficient space in the block. To fix this problem, increase INITRANS or MAXTRANS for the table. This type of TX enqueue corresponds to the wait event ‘enq: TX – allocate ITL’ on 10g and above.
* Waits for TX in mode 4 can also occur if the session is waiting for potential duplicates in a UNIQUE index, which would occur if a second session inserts a value before the first tries to insert the same value, and the second session has not yet committed. This type of enqueue corresponds to the wait event: ‘enq: TX – row lock contention’ on 10g and above.
* ‘Waits for TX in mode 4 can also occur when a transaction is inserting a row into an index and must wait for the end of an index block split being done by another transaction. This type of TX enqueue wait corresponds to the wait event ‘enq: TX – index’ on 10g and above.
You might want to look at the SQL statements sorted by CPU utilization based on the above description.

Taking a look at a couple SQL statements that you posted:

                                                     CPU      Elapsd
  Buffer Gets    Executions  Gets per Exec  %Total Time (s)  Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------                                                          
      3,301,423           91       36,279.4   67.5     0.01      0.01 4086952936
UPDATE IPAO.EMP_MAST SET OSCAL_CODE=:b1 WHERE :b1 < 600

        902,040           30       30,068.0   18.5     0.00      0.00 2333288512
UPDATE IPAO.MON_ACT SET CHEQUE_NO=:b1,CHEQUE_DT=:b2,CHEQUE_AMT=:b3 WHERE V_NO = :b4  AND V_DATE = :b5

 

The first of the two looks interesting. I am a little surprised by the small number for the CPU utilization considering the number of buffer gets. The WHERE clause “WHERE :b1 < 600” seems a little unusual.