Oracle Enqueue Rules Leading to Deadlock Changes Again in 12.1?

1 08 2013

August 1, 2013

Four years ago while co-writing two chapters for an Oracle Database book, an interesting test case was put together to demonstrate how enqueues are handled when multiple sessions are competing for some of the same database resources – the test case was intended to demonstrate the neat, orderly, and predictable process implemented by Oracle Database.  Oracle Database 10.2.0.1 through 10.2.0.4 behaved essentially the same when executing the test case script, while Oracle Database 11.1.0.6, 11.1.0.7, and 11.2.0.1 behaved differently when executing the test case script (11.2.0.2 and 11.2.0.3 behave just like 11.2.0.1 when executing the script).

Oracle Database 11.1.0.x and 11.2.0.x terminated the test case early with a deadlock error.  Jonathan Lewis offered an exceptional explanation of what happened with my test case script in his Lock Horror article.  He also mentioned a couple of interesting notes in comments attached to my article, one of which stated that Oracle Database 9.2.0.5 (or 9.2.0.4) had also introduced a change in enqueue rules related to foreign keys.  Richard Foote put together a related article that explained the changes in locking mode with foreign keys in his Oracle11g: New Locking Modes When Policing FK Constraints article.  Trying not to forget related articles (see the note at the end of this blog article), Tom Kyte also authored a blog article titled Something I recently unlearned… that is somewhat related to the test case script that appeared in the Expert Oracle Practices book.  So, the rules have changed, deadlocks should now be expected when executing the test case script.

I just started experimenting with Oracle Database 12.1.0.1.  My very first experiment with the new database version was to test the behavior of the enqueue script to verify that it results in a deadlock on Oracle Database 12.1.0.1.  Consistency is one of the key factors in a database application – if an application executes:

SELECT 1 + 1 FROM DUAL;

a developer should be reasonably certain that Oracle Database will either return the value 2 or the binary number 10 when the above SQL statement is executed, regardless of whether Oracle Database 6.x or Oracle Database 12.x is used by an application written by the developer.  The same developer should have a reasonable expectation that his application, if it is compatible with Oracle Database 9.0.1, should work pretty much the same way on Oracle Database 12.1.0.1.  But, what happens when Oracle Corp. fixes bugs in Oracle Database?

Consistency is important, but it is also important to recognize that behavior may change consistently.

Let’s reintroduce the test case script from my earlier article (which also appeared in the Expert Oracle Practices book).  Executing this script requires four sessions, each of which is logged in as a different user (to minimize the difficulty associated with deciphering the results of the SQL statements):

  • Session 1 connected as TESTUSER (the owner of the tables)
  • Session 2 connected as USER2
  • Session 3 connected as USER3
  • Session 4 connected as SYS (only to query the various performance views)

First, we need a couple of test tables with a declared foreign key relationship, without an index on the foreign key column.  In Session 1:

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

INSERT INTO
  T1
SELECT
  ROWNUM
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;

COMMIT;

CREATE TABLE T2(
  C1 NUMBER(10) PRIMARY KEY,
  C2 NUMBER(10),
  CONSTRAINT FK_T1_C1 FOREIGN KEY(C2) REFERENCES T1(C1) ENABLE);

INSERT INTO
  T2
SELECT
  ROWNUM,
  ROWNUM
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;

COMMIT;

GRANT ALL ON T1 TO PUBLIC;
GRANT ALL ON T2 TO PUBLIC;

CREATE PUBLIC SYNONYM T1 FOR T1;
CREATE PUBLIC SYNONYM T2 FOR T2;

In Session 1, insert a row into the parent and child tables without issuing a commit:

INSERT INTO T1 VALUES(100010);
INSERT INTO T2 VALUES(100010,100010);

In Session 2, insert a row into the parent and child tables, delete a row in the child table so that the primary key column value of the associated row in the parent table may be modified, and modify the parent row’s primary key column value:

INSERT INTO T1 VALUES(100020);
INSERT INTO T2 VALUES(100020,100020);
DELETE FROM T2 WHERE C1=50;
UPDATE T1 SET C1=100030 WHERE C1=50;

(Session 2 is hung)

Session 3 cannot see that a row was inserted by the now hung session 2, so session 3 attempts to insert a row with the same primary key value.  In Session 3:

INSERT INTO T1 VALUES(100020);

(Session 3 is hung)

The enqueues at this point on Oracle Database 10.2.0.4 differs from those found on Oracle Database 11.1.0.6, and (for consistency) those enqueues differ from what are found on Oracle Database 12.1.0.1.

In Session 4, let’s take a look at the enqueues (note that the join to the V$SESSION_WAIT performance view is unnecessary starting with Oracle Database 10.1.0.x, however I left that join in place to allow easy adaptation of the SQL statement so that it may work with older Oracle Database versions).

SET LINESIZE 165
SET PAGESIZE 1000
SET TRIMSPOOL ON
COLUMN SID FORMAT 9999
COLUMN PROGRAM FORMAT A11
COLUMN USERNAME FORMAT A8
COLUMN LMODE FORMAT 99
COLUMN REQUEST FORMAT 99
COLUMN CN FORMAT 99
COLUMN EVENT FORMAT A30
COLUMN STATE FORMAT A8
COLUMN S_I_W FORMAT 9999
COLUMN WT FORMAT 9999
COLUMN OBJ# FORMAT 999999
COLUMN FILE# FORMAT 999
COLUMN BLOCK# FORMAT 9999999
COLUMN P2 FORMAT 9999999
COLUMN P3 FORMAT 999999

SELECT
  S.SID,
  S.USERNAME,
  S.PROGRAM,
  S.STATUS,
  SW.EVENT,
  SW.WAIT_TIME WT,
  SW.STATE,
  SW.SECONDS_IN_WAIT S_I_W,
  S.SQL_ID,
  S.SQL_CHILD_NUMBER CN,
  S.ROW_WAIT_OBJ# OBJ#,
  S.ROW_WAIT_FILE# FILE#,
  S.ROW_WAIT_BLOCK# BLOCK#,
  S.ROW_WAIT_ROW# ROW#,
  SW.P1,
  SW.P2,
  SW.P3
FROM
  V$SESSION_WAIT SW,
  V$SESSION S
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 USERNAME PROGRAM     STATUS   EVENT                             WT STATE    S_I_W SQL_ID         CN    OBJ# FILE#   BLOCK# ROW#         P1       P2      P3
----- -------- ----------- -------- ------------------------------ ----- -------- ----- ------------- --- ------- ----- -------- ---- ---------- -------- -------
  184 USER2    sqlplus.exe ACTIVE   enq: TM - contention               0 WAITING     89 4rtg0hv0atfkx   0      -1     0        0    0 1414332421    91943       0
  243 USER3    sqlplus.exe ACTIVE   enq: TX - row lock contention      0 WAITING     49 cv338j6z2530g   0      -1     0        0    0 1415053316    65548    1531

For comparison, here is the output of the same SQL statement on 11.1.0.7 from the earlier blog article:

__SID USERNAME PROGRAM     STATUS   EVENT                             WT STATE    S_I_W SQL_ID         CN    OBJ# FILE#   BLOCK# ROW#         P1       P2      P3
----- -------- ----------- -------- ------------------------------ ----- -------- ----- ------------- --- ------- ----- -------- ---- ---------- -------- -------
  307 USER2    sqlplus.exe ACTIVE   enq: TM - contention               0 WAITING    422 4rtg0hv0atfkx   0      -1     0        0    0 1414332421    82913       0
  314 USER3    sqlplus.exe ACTIVE   enq: TM - contention               0 WAITING    407 cv338j6z2530g   0      -1     0        0    0 1414332419    82913       0

For comparison, here is the output of the same SQL statement on 10.2.0.4 from the earlier blog article:

__SID USERNAME PROGRAM     STATUS   EVENT                             WT STATE    S_I_W SQL_ID         CN    OBJ# FILE#   BLOCK# ROW#         P1       P2      P3
----- -------- ----------- -------- ------------------------------ ----- -------- ----- ------------- --- ------- ----- -------- ---- ---------- -------- -------
  204 USER2    sqlplus.exe ACTIVE enq: TM - contention                 0 WAITING    213 4rtg0hv0atfkx   0      -1     0        0    0 1414332421    16472       0
  217 USER3    sqlplus.exe ACTIVE enq: TM - contention                 0 WAITING    201 cv338j6z2530g   0      -1     0        0    0 1414332418    16472       0

… USER3 on 12.1.0.1 seems to not be waiting on a table level (TM) enqueue.

In Session 4, let’s try the second SQL statement to examine the lock modes:

SELECT
  S.SID,
  S.USERNAME,
  S.PROGRAM,
  S.SQL_ID,
  S.SQL_CHILD_NUMBER CN,
  S.ROW_WAIT_OBJ#,
  S.ROW_WAIT_FILE#,
  S.ROW_WAIT_BLOCK#,
  S.ROW_WAIT_ROW#,
  L.LMODE,
  L.REQUEST,
  L.ID1,
  L.ID2,
  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 USERNAME PROGRAM     SQL_ID         CN ROW_WAIT_OBJ# ROW_WAIT_FILE# ROW_WAIT_BLOCK# ROW_WAIT_ROW# LMODE REQUEST        ID1        ID2 TY    BLOCK
----- -------- ----------- ------------- --- ------------- -------------- --------------- ------------- ----- ------- ---------- ---------- -- --------
  127 TESTUSER sqlplus.exe                              -1              0               0             0     3       0      91943          0 TM        1
  184 USER2    sqlplus.exe 4rtg0hv0atfkx   0            -1              0               0             0     3       5      91943          0 TM        1
  184 USER2    sqlplus.exe 4rtg0hv0atfkx   0            -1              0               0             0     6       0      65548       1531 TX        1
  243 USER3    sqlplus.exe cv338j6z2530g   0            -1              0               0             0     2       0      91943          0 TM        0
  243 USER3    sqlplus.exe cv338j6z2530g   0            -1              0               0             0     0       4      65548       1531 TX        0

For comparison, here is the output of the same SQL statement on 11.1.0.7 from the earlier blog article:

__SID USERNAME PROGRAM     SQL_ID         CN ROW_WAIT_OBJ# ROW_WAIT_FILE# ROW_WAIT_BLOCK# ROW_WAIT_ROW# LMODE REQUEST        ID1        ID2 TY    BLOCK
----- -------- ----------- ------------- --- ------------- -------------- --------------- ------------- ----- ------- ---------- ---------- -- --------
  320 TESTUSER sqlplus.exe 0vbusv12hnbk6   0         12517              1           29656             0     3       0      82913          0 TM        1
  307 USER2    sqlplus.exe 4rtg0hv0atfkx   0            -1              0               0             0     3       5      82913          0 TM        1
  314 USER3    sqlplus.exe cv338j6z2530g   0            -1              0               0             0     0       3      82913          0 TM        0

For comparison, here is the output of the same SQL statement on 10.2.0.4 from the earlier blog article:

__SID USERNAME PROGRAM     SQL_ID         CN ROW_WAIT_OBJ# ROW_WAIT_FILE# ROW_WAIT_BLOCK# ROW_WAIT_ROW# LMODE REQUEST        ID1        ID2 TY    BLOCK
----- -------- ----------- ------------- --- ------------- -------------- --------------- ------------- ----- ------- ---------- ---------- -- --------
  213 TESTUSER sqlplus.exe 0vbusv12hnbk6   0             0              2             799             0     3       0      16472          0 TM        1
  204 USER2    sqlplus.exe 4rtg0hv0atfkx   0            -1              0               0             0     3       5      16472          0 TM        0
  217 USER3    sqlplus.exe cv338j6z2530g   0            -1              0               0             0     0       2      16472          0 TM        0

So, on Oracle Database 12.1.0.1, USER3 is not waiting on a table level (TM) equeue (it is holding a level 2 TM enqueue, while on 10.2.0.4 that session was trying to acquire a level 2 TM lock, and on 11.1.0.7 that session was trying to acquire a level 3 TM lock), it is instead waiting on a row level (TX – transaction) enqueue that is held in exclusive mode (level 6) by USER2.  Quite honestly, that result is similar to what I was hoping to see four years ago when the test script was put together, because USER3 really is waiting due to a potential primary key collision, if session 2 issues a commit.

Session 2 is hung, so it cannot issue a commit.  So, in Session 1:

COMMIT;

Session 2 is no longer hung, and now shows:

1 row updated.

Session 3, of course, remains hung waiting for Session 2 to either issue a COMMIT or a ROLLBACK to resolve the potential primary key collision.

For comparison, Session 3 on 11.1.0.7 from the earlier blog article showed the following:

INSERT INTO T1 VALUES(100020)
            *
ERROR at line 1:
ORA-00060: deadlock detected while waiting for resource

… and Session 2 showed the following on 11.1.0.7:

1 row updated.

Is it possible that the Session 2 could have displayed a deadlock message, rather than Session 3 showing a deadlock message?  I seem to remember reading that there is a good chance that the session that has been in the enqueue the longest could be selected as the “vicitim” of the deadlock, but I might be incorrectly remembering that rule.  Oracle Database really did not completely resolve the deadlock, nor did it “kill” session 3 (as too many books and blog article state would happen) when the deadlock message appeared in that session’s SQL*Plus session.

For comparison, Oracle Database 10.2.0.4 behaved similar to Oracle Database 12.1.0.1, with Session 2 showing 1 row updated, and Session 3 remaining hung.  The more things change, the more they stay the same?

Thoughts?  Curious about the test cases found on the web pages that I linked to earlier?  Does Oracle Database 12.1.0.1 behave more like 11.2.0.3 or 10.2.0.4 when foreign key columns are not properly indexed?





Lock Watching – What is Wrong with this SQL Statement?

3 06 2010

June 3, 2010

I came across an interesting SQL statement that is described as identifying blocking transactions:

select s1.username blkg_user, s1.machine blkg_ws, s1.sid blkg_sid,
       s2.username wait_user, s2.machine wait_ws, s2.sid wait_sid,
       lo.object_id blkd_obj_id, do.owner, do.object_name
from v$lock l1, v$session s1, v$lock l2, v$session s2,
     v$locked_object lo, dba_objects do
where s1.sid = l1.sid
  and s2.sid = l2.sid
  and l1.id1 = l2.id1
  and s1.sid = lo.session_id
  and lo.object_id = do.object_id
  and l1.block = 1
  and l2.request > 0;

The SQL statement is a bit different from the one that I typically use for determining enqueues.  The documentation also includes a SQL statement for determining enqueues.

What, if anything, is wrong with the above SQL statement?  If you need a test case, try the one found in this article.  I suspect that there may be more than one answer.





Deadlock on Oracle 11g but Not on 10g

7 01 2010

January 7, 2010

Is it possible to trigger a deadlock on Oracle Database 11.1.0.6, 11.1.0.7, and 11.2.0.1 when the exact same procedure does not trigger a deadlock on Oracle Database 10.2.0.4?  Trace files containing deadlocks always contain the following advice:

The following deadlock is not an ORACLE error. It is a deadlock due to user error in the design of an application or from issuing incorrect ad-hoc SQL.

In short, the above states that deadlocks are programming and/or end-user errors.

A couple of months after I generated a test case like the one below, I read an interesting blog article by Mark Bobak, a fellow OakTable Network member and frequent contributor to the Oracle OTN forums and Oracle-L list.  I then started to wonder if the test case I put together applied to Mark’s article (clarification: my test case was built roughly a year after Mark’s article was written, I only recently found Mark’s article).

I have a few favorite Oracle books, and I thought that I would quote from two of those books:

Expert Oracle Database Architecture: 9i and 10g Programming Techniques and Solutions

“So, when do you not need to index a foreign key? The answer is, in general, when the following conditions are met:

  • You do not delete from the parent table.
  • You do not update the parent table’s unique/primary key value (watch for unintended updates to the primary key by tools!).
  • You do not join from the parent to the child (like DEPT to EMP).”

Page 302 of the book “Expert One-On-One” and the reprint Expert Oracle, Signature Edition state essentially the same thing as the above book.

Oracle Wait Interface: a Practical Guide to Performance Diagnostics & Tuning

“Unindexed foreign keys are no longer an issue starting in Oracle9i Database.”

Interesting…

I have not read the following book, but found it through a Google search.  This book seems to take the middle ground:

OCA Oracle Database 11g: Administration I Exam Guide

“However, you should always create indexes on the foreign key columns within the child table for performance reasons: a DELETE on the parent table will be much faster if Oracle can use an index to determine whether there are any rows in the child table referencing the row that is being deleted.” 

OK, combining the three quotes – in general, there are only 3 cases when foreign key columns do not need to be indexed, as of Oracle 9i it is no longer necessary to index foreign key columns, but in Oracle 11g creating an index on a foreign key column will speed up deletes on the parent table.

Let’s keep the above in mind while we trigger a deadlock in Oracle 11.1.0.7. Refer back to the articles on Enqueues and Deadlocks to see if you are able to determine what happens in the test case (or more accurately WHY it happens) (clarification: this test case simulates a “screen painter” type program that updates every column in a row based on the fields on screen – the same behavior should be present if the primary key value in the parent table is updated to the same value, rather than a different value – it also relies on the fact that a row that is inserted by one session but not committed is not visible to another session until the first session commits).

First, we need a couple test tables:

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

INSERT INTO
  T1
SELECT
  ROWNUM
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;

COMMIT;

CREATE TABLE T2(
  C1 NUMBER(10) PRIMARY KEY,
  C2 NUMBER(10),
  CONSTRAINT FK_T1_C1 FOREIGN KEY(C2) REFERENCES T1(C1) ENABLE);

INSERT INTO
  T2
SELECT
  ROWNUM,
  ROWNUM
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;

COMMIT;

GRANT ALL ON T1 TO PUBLIC;
GRANT ALL ON T2 TO PUBLIC;

CREATE PUBLIC SYNONYM T1 FOR T1;
CREATE PUBLIC SYNONYM T2 FOR T2;

OK, we have two tables with a foreign key relationship, and no index on the foreign key column.  Now, we need four sessions:

  • Session 1 connected as TESTUSER (the owner of the tables)
  • Session 2 connected as USER2
  • Session 3 connected as USER3
  • Session 4 connected as SYS (only to query the various performance views)

Session 1:

INSERT INTO T1 VALUES(100010);
INSERT INTO T2 VALUES(100010,100010);

Session 2:

INSERT INTO T1 VALUES(100020);
INSERT INTO T2 VALUES(100020,100020);
DELETE FROM T2 WHERE C1=50;
UPDATE T1 SET C1=100030 WHERE C1=50;

{session 2 hangs}

Session 3:

INSERT INTO T1 VALUES(100020);

{session 3 hangs}

Session 4:

SELECT /*+ ORDERED */
  S.SID,
  S.USERNAME,
  S.PROGRAM,
  S.STATUS,
  SW.EVENT,
  SW.WAIT_TIME WT,
  SW.STATE,
  SW.SECONDS_IN_WAIT S_I_W,
  S.SQL_ID,
  S.SQL_ADDRESS,
  S.SQL_HASH_VALUE,
  S.SQL_CHILD_NUMBER,
  S.ROW_WAIT_OBJ# OBJ#,
  S.ROW_WAIT_FILE# FILE#,
  S.ROW_WAIT_BLOCK# BLOCK#,
  S.ROW_WAIT_ROW# ROW#,
  SW.P1,
  SW.P2,
  SW.P3
FROM
  V$SESSION_WAIT SW,
  V$SESSION S
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 USERNAME PROGRAM     STATUS EVENT                WT STATE   S_I_W SQL_ID        SQL_ADDR SQL_HV     CN OBJ# FILE# BLOCK# ROW#         P1    P2 P3
--- -------- ----------- ------ -------------------- -- ------- ----- ------------- -------- ---------- -- ---- ----- ------ ---- ---------- ----- --
307 USER2    sqlplus.exe ACTIVE enq: TM - contention  0 WAITING   422 4rtg0hv0atfkx 224E2B7C 3232545373  0   -1     0      0    0 1414332421 82913  0
314 USER3    sqlplus.exe ACTIVE enq: TM - contention  0 WAITING   407 cv338j6z2530g 224DAE38 3189935119  0   -1     0      0    0 1414332419 82913  0

 

SELECT
  S.SID,
  S.USERNAME,
  S.PROGRAM,
  S.SQL_ID,
  S.SQL_ADDRESS,
  S.SQL_HASH_VALUE,
  S.SQL_CHILD_NUMBER CN,
  S.ROW_WAIT_OBJ#,
  S.ROW_WAIT_FILE#,
  S.ROW_WAIT_BLOCK#,
  S.ROW_WAIT_ROW#,
  L.LMODE,
  L.REQUEST,
  L.ID1,
  L.ID2,
  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 USERNAME PROGRAM     SQL_ID        SQL_ADDR SQL_HASH_VALUE CN ROW_WAIT_OBJ# ROW_WAIT_FILE# ROW_WAIT_BLOCK# ROW_WAIT_ROW# LMODE REQUEST ID1   ID2 TY BLOCK
--- -------- ----------- ------------- -------- -------------- -- ------------- -------------- --------------- ------------- ----- ------- ----- --- -- -----
307 USER2    sqlplus.exe 4rtg0hv0atfkx 224E2B7C     3232545373  0            -1              0               0             0     3       5 82913   0 TM     1
314 USER3    sqlplus.exe cv338j6z2530g 224DAE38     3189935119  0            -1              0               0             0     0       3 82913   0 TM     0
320 TESTUSER sqlplus.exe 0vbusv12hnbk6 22480E10     1158295110  0         12517              1           29656             0     3       0 82913   0 TM     1

 

Session 1:

COMMIT;

Session 3 shows the following:

INSERT INTO T1 VALUES(100020)
            *
ERROR at line 1:
ORA-00060: deadlock detected while waiting for resource

Session 2 shows the following:

1 row updated.

The trace file contains the following deadlock information:

[Transaction Deadlock]

The following deadlock is not an ORACLE error. It is a
deadlock due to user error in the design of an application
or from issuing incorrect ad-hoc SQL. The following
information may aid in determining the deadlock:

Deadlock graph:
 ---------Blocker(s)--------  ---------Waiter(s)---------
Resource Name          process session holds waits  process session holds waits
TM-000143e1-00000000        21     314    SX             23     307    SX   SSX
TX-0009000d-000030d3        23     307     X             21     314           S

session 314: DID 0001-0015-00000006 session 307: DID 0001-0017-00000001
session 307: DID 0001-0017-00000001 session 314: DID 0001-0015-00000006

Rows waited on:
  Session 314: no row
  Session 307: obj - rowid = 000143E0 - AAAUPgAAFAAFDpsAAA
  (dictionary objn - 82912, file - 5, block - 1325676, slot - 0)

----- Information for the OTHER waiting sessions -----
Session 307:
  sid: 307 ser: 2 audsid: 1210519 user: 186/USER2 flags: 0x100045
  pid: 23 O/S info: user: SYSTEM, term: TESTBOX, ospid: 940
    image: ORACLE.EXE (SHAD)
  client details:
    O/S info: user: TEST, term: TESTBOX, ospid: 1616:1264
    machine: TESTBOX program: sqlplus.exe
    application name: SQL*Plus, hash value=3669949024
  current SQL:

UPDATE T1 SET C1=100030 WHERE C1=50  

Interesting deadlock.  Now, let’s try the same test with Oracle 10.2.0.4:

The table definitions:

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

INSERT INTO
  T1
SELECT
  ROWNUM
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;

COMMIT;

CREATE TABLE T2(
  C1 NUMBER(10) PRIMARY KEY,
  C2 NUMBER(10),
  CONSTRAINT FK_T1_C1 FOREIGN KEY(C2) REFERENCES T1(C1) ENABLE);

INSERT INTO
  T2
SELECT
  ROWNUM,
  ROWNUM
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;

COMMIT;

GRANT ALL ON T1 TO PUBLIC;
GRANT ALL ON T2 TO PUBLIC;

CREATE PUBLIC SYNONYM T1 FOR T1;
CREATE PUBLIC SYNONYM T2 FOR T2;

Now for the test:

Session 1:

INSERT INTO T1 VALUES(100010);
INSERT INTO T2 VALUES(100010,100010);

Session 2:

INSERT INTO T1 VALUES(100020);
INSERT INTO T2 VALUES(100020,100020);
DELETE FROM T2 WHERE C1=50;
UPDATE T1 SET C1=100030 WHERE C1=50;

{session 2 hangs}

Session 3:

INSERT INTO T1 VALUES(100020);

{session 3 hangs}

Session 4:

SELECT /*+ ORDERED */
  S.SID,
  S.USERNAME,
  S.PROGRAM,
  S.STATUS,
  SW.EVENT,
  SW.WAIT_TIME WT,
  SW.STATE,
  SW.SECONDS_IN_WAIT S_I_W,
  S.SQL_ID,
  S.SQL_ADDRESS,
  S.SQL_HASH_VALUE,
  S.SQL_CHILD_NUMBER,
  S.ROW_WAIT_OBJ# OBJ#,
  S.ROW_WAIT_FILE# FILE#,
  S.ROW_WAIT_BLOCK# BLOCK#,
  S.ROW_WAIT_ROW# ROW#,
  SW.P1,
  SW.P2,
  SW.P3
FROM
  V$SESSION_WAIT SW,
  V$SESSION S
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 USERNAME PROGRAM     STATUS EVENT                WT STATE   S_I_W SQL_ID        SQL_ADDR SQL_HV     CN OBJ# FILE# BLOCK# ROW#         P1    P2 P3
--- -------- ----------- ------ -------------------- -- ------- ----- ------------- -------- ---------- -- ---- ----- ------ ---- ---------- ----- --
204 USER2    sqlplus.exe ACTIVE enq: TM - contention  0 WAITING   213 4rtg0hv0atfkx 2AF83608 3232545373  0   -1     0      0    0 1414332421 16472  0
217 USER3    sqlplus.exe ACTIVE enq: TM - contention  0 WAITING   201 cv338j6z2530g 2AF85A5C 3189935119  0   -1     0      0    0 1414332418 16472  0

 

SELECT
  S.SID,
  S.USERNAME,
  S.PROGRAM,
  S.SQL_ID,
  S.SQL_ADDRESS,
  S.SQL_HASH_VALUE,
  S.SQL_CHILD_NUMBER CN,
  S.ROW_WAIT_OBJ#,
  S.ROW_WAIT_FILE#,
  S.ROW_WAIT_BLOCK#,
  S.ROW_WAIT_ROW#,
  L.LMODE,
  L.REQUEST,
  L.ID1,
  L.ID2,
  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 USERNAME PROGRAM     SQL_ID        SQL_ADDR SQL_HASH_VALUE CN ROW_WAIT_OBJ# ROW_WAIT_FILE# ROW_WAIT_BLOCK# ROW_WAIT_ROW# LMODE REQUEST ID1   ID2 TY BLOCK
--- -------- ----------- ------------- -------- -------------- -- ------------- -------------- --------------- ------------- ----- ------- ----- --- -- -----
213 TESTUSER sqlplus.exe 0vbusv12hnbk6 2AF78CC4     1158295110  0             0              2             799             0     3       0 16472   0 TM     1
204 USER2    sqlplus.exe 4rtg0hv0atfkx 2AF83608     3232545373  0            -1              0               0             0     3       5 16472   0 TM     0
217 USER3    sqlplus.exe cv338j6z2530g 2AF85A5C     3189935119  0            -1              0               0             0     0       2 16472   0 TM     0

Session 1:

COMMIT;

Session 3:

{session 3 remains hung}

Session 2:

1 row updated.

Session 4:

SELECT /*+ ORDERED */
  S.SID,
  S.USERNAME,
  S.PROGRAM,
  S.STATUS,
  SW.EVENT,
  SW.WAIT_TIME WT,
  SW.STATE,
  SW.SECONDS_IN_WAIT S_I_W,
  S.SQL_ID,
  S.SQL_ADDRESS,
  S.SQL_HASH_VALUE,
  S.SQL_CHILD_NUMBER,
  S.ROW_WAIT_OBJ# OBJ#,
  S.ROW_WAIT_FILE# FILE#,
  S.ROW_WAIT_BLOCK# BLOCK#,
  S.ROW_WAIT_ROW# ROW#,
  SW.P1,
  SW.P2,
  SW.P3
FROM
  V$SESSION_WAIT SW,
  V$SESSION S
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 USERNAME PROGRAM     STATUS EVENT                         WT STATE   S_I_W SQL_ID        SQL_ADDR SQL_HV     CN OBJ# FILE# BLOCK# ROW#         P1     P2   P3
--- -------- ----------- ------ ----------------------------- -- ------- ----- ------------- -------- ---------- -- ---- ----- ------ ---- ---------- ------ ----
217 USER3    sqlplus.exe ACTIVE enq: TX - row lock contention  0 WAITING   380 cv338j6z2530g 2AF85A5C 3189935119  0   -1     0      0    0 1415053316 458788 1297

 

SELECT
  S.SID,
  S.USERNAME,
  S.PROGRAM,
  S.SQL_ID,
  S.SQL_ADDRESS,
  S.SQL_HASH_VALUE,
  S.SQL_CHILD_NUMBER CN,
  S.ROW_WAIT_OBJ#,
  S.ROW_WAIT_FILE#,
  S.ROW_WAIT_BLOCK#,
  S.ROW_WAIT_ROW#,
  L.LMODE,
  L.REQUEST,
  L.ID1,
  L.ID2,
  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 USERNAME PROGRAM     SQL_ID        SQL_ADDR SQL_HASH_VALUE CN ROW_WAIT_OBJ# ROW_WAIT_FILE# ROW_WAIT_BLOCK# ROW_WAIT_ROW# LMODE REQUEST ID1    ID2  TY BLOCK
--- -------- ----------- ------------- -------- -------------- -- ------------- -------------- --------------- ------------- ----- ------- ------ ---- -- -----
217 USER3    sqlplus.exe cv338j6z2530g 2AF85A5C     3189935119  0            -1              0               0             0     0       4 458788 1297 TX     0
204 USER2    sqlplus.exe               00                    0               -1              0               0             0     6       0 458788 1297 TX     1

So, why did Oracle 11.1.0.7 deadlock while 10.2.0.4 did not deadlock (11.1.0.6 and 11.2.0.1 will also deadlock)?





Enqueue Experimentations

6 12 2009

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.








Follow

Get every new post delivered to your Inbox.

Join 142 other followers