Bug With “enq: DX – contention” in wait class “Other”

Recently got a request as database responding slow and operations are unusual, As a part of database slowness first reviewed OS level what is the CPU utilization and how much processes and what processes are consuming CPU and found to be oracle Database processes are consuming from 90% to 100% with around 30 processes.

Database Version: 11.1.0.7.0 on Linux

Now connected to database for the AWR report to see what are the wait events and what can be issue with performance, I can see wait events with 85% of Activity and below is the information form the advisory reports and wait event “enq: DX – Contention” is reporting with “Wait class Other”.

   Description                 Active Sessions      Recommendations
                               Percent of Activity
   --------------------------  -------------------  ---------------
1  Unusual "Other" Wait Event  1.71 | 85.54         5
2  Unusual "Other" Wait Event  .29 | 14.24          4
Finding 1: Unusual "Other" Wait Event
Impact is 1.71 active sessions, 85.54% of total activity.
---------------------------------------------------------
Wait event "enq: DX - contention" in wait class "Other" was consuming

Usually, My first approach to check for any Unusual “other” wait event i will start look at locks and also the session blocks as a preliminary step. As expected found session blocking.

BLOCKING
------------------------------
SID 42 is blocking  43
SID 28 is blocking  138

Now lets see more in detail with view “v$session_wait“, what are the events, event state and how much time it is spending for each event.

EVENT                           STATE               WAIT_TIME_MICRO TIME_REMAINING_MICRO TIME_SINCE_LAST_WAIT_MICRO
------------------------------- ------------------- --------------- -------------------- --------------------------
enq: DX - contention            WAITING                     1108966              4891034                          0
inactive transaction branch     WAITING                      336971               663029                          0
SQL*Net more data to client     WAITING               1094640039070                   -1                          0
SQL*Net more data to client     WAITING               1097358489246                   -1                          0

For the above sessions, all the events are in “Waiting” state,  Also you can see amount of time waited(WAIT_TIME_MICRO). If the session is currently waiting, then the value is the time spent in the current wait. If the session is currently not in a wait, then the value is the amount of time waited in the last wait and “TIME_REMAINING_MICRO” column refers to the multiple meanings depending on the value of each wait event, If value is “>0” then which refers amount of time remaining in the current wait and if it is “-1″ then it means session can indefinitely wait in the current wait”. From the view “v$session” of column “WAIT_TIME” , If any sessions are waiting with a zero value means the session is currently waiting.

 SQL> select sid,event,seq#,p1,p1raw,p2,p3 from v$session  where wait_time=0;
       SID EVENT                                SEQ#         P1 P1RAW                    P2         P3
---------- ------------------------------ ---------- ---------- ---------------- ---------- ----------
        28 SQL*Net more data to client          2074 1413697536 0000000054435000       8144          0
        42 SQL*Net more data to client         19526 1413697536 0000000054435000       8150          0
        43 enq: DX - contention                49987 1146617862 0000000044580006         62          0
       138 enq: DX - contention                49215 1146617862 0000000044580006         30          0

So all the sessions are waiting, they all are related to the session blocking “SID”.  🙂
Now the decision is to kill the possible blocking sessions? Of course now you can resolve it. If the same issue caused again and again? For further more analysis for any such blocks/hang analysis suggested to generate system state dumps by using “ALTER SESSION SET EVENTS ‘IMMEDIATE TRACE NAME SYSTEMSTATE LEVEL 258’;” Now i can able to got much information by the system state dump as below.

Waiter:

  Current Wait Stack:
     0: waiting for 'SQL*Net more data to client'
        driver id=54435000, #bytes=1fd0, =0
        wait_id=2073 seq_num=2074 snap_id=1
        wait times: snap=18228 min 40 sec, exc=18228 min 40 sec, total=18228 min 40 sec
        wait times: max=infinite
        wait counts: calls=0 os=0
        in_wait=1 iflags=0x5a0
    There is at least one session blocked by this session.
    Dumping one waiter:
      inst: 1, sid: 138, ser: 6349
      wait event: 'enq: DX - contention'
        p1: 'name|mode'=0x44580006
        p2: 'transaction entry #'=0x1e
        p3: '0'=0x0
      row_wait_obj#: 4294967295, block#: 0, row#: 0, file# 0
      min_blocked_time: 3 secs, waiter_cache_ver: 64532
    Wait State:
      auto_close=0 flags=0x22 boundary=(nil)/-1

Blocker:

Current Wait Stack:
     0: waiting for 'enq: DX - contention'
        name|mode=44580006, transaction entry #=3e, 0=0
        wait_id=313066 seq_num=50927 snap_id=1
        wait times: snap=2.163796 sec, exc=2.163796 sec, total=2.163796 sec
        wait times: max=6.000000 sec
        wait counts: calls=2 os=2
        in_wait=1 iflags=0x15a0
    There is at least one session blocking this session.
    Dumping one blocker:
      inst: 1, sid: 42, ser: 19547
    Wait State:
      auto_close=0 flags=0x22 boundary=(nil)/-1
    Session Wait History:
     0: waited for 'inactive transaction branch

Apart from the wait events,  The same sessions you can see below consumed CPU Time. Other sessions waiting on the above may exhibit higher than usual waits on related events “Enq: DX – Contention‘, or “Inactive Trasaction Branch“. May be

   SID Serial#    Status  Oracle User  O/S User O/S PID Session Program             Machine              CPU
------ ------- --------- ------------ --------- ------- -------------------- -------------- ----------------
    42   19547    ACTIVE     RMSADMIN     vaira    6296 oracle@rmsuatdb (          rmsuatdb           24,753
    28    8779    ACTIVE     RMSADMIN     vaira   28500 oracle@rmsuatdb (          rmsuatdb            2,531

So far based on the findings, High CPU by the sessions trying to abort the distributed transactions, these sessions are holding a DX enqueue and more associated with distributed transaction activity. If you go in detail to the system state dump files, you can see “kssdct()” operation and it should be for short lived and should not appear in successive system states. For the same kind of wait events and high CPU listed “bug:8552942” for the 10.2.0.4 and patch is available for that fix. However if patch not available for upper versions(Ex: 11gR1) next step is to submit alert, traces, system trace to Support for related Patch to fix.

–Happy Reading–