Know more about Enqueue Deadlock Detection

今天在 ORACLE ALLSTAR群里讨论了一个关于队列锁死锁检测的问题，原帖子在这里。 有同学指出对于enqueue lock的死锁检测应当是每3 秒钟检测一次，这样说的依据是通过一个简单可重复的实验可以证明在实际出现ora-00060 dead lock错前process等待了3s:  

SQL> select * from v$version;

BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.5.0 - 64bi
PL/SQL Release 10.2.0.5.0 - Production
CORE    10.2.0.5.0      Production
TNS for Linux: Version 10.2.0.5.0 - Production
NLSRTL Version 10.2.0.5.0 - Production

SQL> select * from global_name;

GLOBAL_NAME
--------------------------------------------------------------------------------
www.oracledatabase12g.com

PROCESS A:

set timing on;
update maclean1 set t1=t1+1;

PROCESS B:

update maclean2 set t1=t1+1;

PROCESS A:
update maclean2 set t1=t1+1;

PROCESS B:

update maclean1 set t1=t1+1;

等待3s后 PROCESS A 会报

ERROR at line 1:
ORA-00060: deadlock detected while waiting for resource

Elapsed: 00:00:03.02

    可以看到Process A在检测到死锁之前确实等待了 3s，而且这是一个可以重复的实验，很具有说服力。 事实真的是这样的吗？   来看下面的演示：  

SQL> col name for a30
SQL> col value for a5
SQL> col DESCRIB for a50
SQL> set linesize 140 pagesize 1400
SQL> SELECT x.ksppinm NAME, y.ksppstvl VALUE, x.ksppdesc describ
  2   FROM SYS.x$ksppi x, SYS.x$ksppcv y
  3   WHERE x.inst_id = USERENV ('Instance')
  4   AND y.inst_id = USERENV ('Instance')
  5   AND x.indx = y.indx
  6  AND x.ksppinm='_enqueue_deadlock_scan_secs';

NAME                           VALUE DESCRIB
------------------------------ ----- --------------------------------------------------
_enqueue_deadlock_scan_secs    0    deadlock scan interval

SQL> alter system set "_enqueue_deadlock_scan_secs"=18 scope=spfile;

System altered.

Elapsed: 00:00:00.01

SQL> startup force;
ORACLE instance started.

Total System Global Area  851443712 bytes
Fixed Size                  2100040 bytes
Variable Size             738198712 bytes
Database Buffers          104857600 bytes
Redo Buffers                6287360 bytes
Database mounted.
Database opened.

PROCESS A:

SQL> set timing on;
SQL> update maclean1 set t1=t1+1;

1 row updated.

Elapsed: 00:00:00.06

Process B

SQL> update maclean2 set t1=t1+1;

1 row updated.

SQL>  update maclean1 set t1=t1+1;

Process A:
SQL>
SQL> alter session set events '10704 trace name context forever,level 10:10046 trace name context forever,level 8';

Session altered.

SQL> update maclean2 set t1=t1+1;
update maclean2 set t1=t1+1
       *
ERROR at line 1:

ORA-00060: deadlock detected while waiting for resource 

Elapsed: 00:00:18.05

ksqcmi: TX,90011,4a9 mode=6 timeout=21474836
WAIT #12: nam='enq: TX - row lock contention' ela= 2930070 name|mode=1415053318 usn<<16 | slot=589841 sequence=1193 obj#=56810 tim=1308114759849120
WAIT #12: nam='enq: TX - row lock contention' ela= 2930636 name|mode=1415053318 usn<<16 | slot=589841 sequence=1193 obj#=56810 tim=1308114762779801
WAIT #12: nam='enq: TX - row lock contention' ela= 2930439 name|mode=1415053318 usn<<16 | slot=589841 sequence=1193 obj#=56810 tim=1308114765710430
*** 2012-06-12 09:58:43.089
WAIT #12: nam='enq: TX - row lock contention' ela= 2931698 name|mode=1415053318 usn<<16 | slot=589841 sequence=1193 obj#=56810 tim=1308114768642192
WAIT #12: nam='enq: TX - row lock contention' ela= 2930428 name|mode=1415053318 usn<<16 | slot=589841 sequence=1193 obj#=56810 tim=1308114771572755
WAIT #12: nam='enq: TX - row lock contention' ela= 2931408 name|mode=1415053318 usn<<16 | slot=589841 sequence=1193 obj#=56810 tim=1308114774504207
DEADLOCK DETECTED ( ORA-00060 )
[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:

      以上可以看到Process A从'enq: TX - row lock contention' 等待到触发ORA-00060 deadlock detected的时间从3s 变成了 18s ， 恰巧是hidden parameter "_enqueue_deadlock_scan_secs"所指定的值，该隐藏参数默认为0。   我们再来看另一个实验：  

SQL> alter system set "_enqueue_deadlock_scan_secs"=4 scope=spfile;

System altered.

Elapsed: 00:00:00.01

SQL> alter system set "_enqueue_deadlock_time_sec"=9 scope=spfile;

System altered.

Elapsed: 00:00:00.00

SQL> startup force;
ORACLE instance started.

Total System Global Area  851443712 bytes
Fixed Size                  2100040 bytes
Variable Size             738198712 bytes
Database Buffers          104857600 bytes
Redo Buffers                6287360 bytes
Database mounted.
Database opened.

SQL> set linesize 140 pagesize 1400

SQL> show parameter dead

NAME                                 TYPE                             VALUE
------------------------------------ -------------------------------- ------------------------------
_enqueue_deadlock_scan_secs          integer                          4
_enqueue_deadlock_time_sec           integer                          9

SQL> set timing on

SQL> select * from maclean1 for update wait 8; 
        T1
----------
        11

Elapsed: 00:00:00.01

PROCESS B

SQL> select * from maclean2 for update wait 8;

        T1
----------
         3

SQL> select * from maclean1 for update wait 8;
select * from maclean1 for update wait 8

PROCESS A

SQL> select * from maclean2 for update wait 8;
select * from maclean2 for update wait 8
              *
ERROR at line 1:
ORA-30006: resource busy; acquire with WAIT timeout expired

Elapsed: 00:00:08.00

    以上我们可以看到 当指定 select for update wait的enqueue request timeout 等待超时为8s时 ，虽然我们指定了"_enqueue_deadlock_scan_secs"=4(deadlock scan interval )，即4s做一次deadlock detected，但是实际Process A并没有做deadlock 的检测， 为什么这样说？   因为Process A在这里等待8s后raised的是"ORA-30006: resource busy; acquire with WAIT timeout expired"错误，而非ORA-00060，这就说明了process A没有做死锁检测。   这是因为隐藏参数"_enqueue_deadlock_time_sec"(requests with timeout <= this will not have deadlock detection)的存在，当enqueue request time < "_enqueue_deadlock_time_sec"时Server process就会放弃做dead lock detection，这是因为即然指定了enqueue request 超时的时间且timeout值又不是很大(_enqueue_deadlock_time_sec默认值为5，即timeout<5s)，那么不做死锁检测也是可以接受的；而对于指定的timeout>"_enqueue_deadlock_time_sec"的情况，Oracle仍需要定时做死锁检测避免长时间的死锁发生。   我们再来看下面的演示：    

SQL> show parameter dead

NAME                                 TYPE                             VALUE
------------------------------------ -------------------------------- ------------------------------
_enqueue_deadlock_scan_secs          integer                          4
_enqueue_deadlock_time_sec           integer                          9

Process A:

SQL> set timing on;
SQL> select * from maclean1 for update wait 10;  

        T1
----------
        11

Process B:

SQL> select * from maclean2 for update wait 10;  

        T1
----------
         3

SQL> select * from maclean1 for update wait 10;  

PROCESS A:

SQL> select * from maclean2 for update wait 10;
select * from maclean2 for update wait 10
              *
ERROR at line 1:
ORA-00060: deadlock detected while waiting for resource

Elapsed: 00:00:06.02

    这一次我们指定 select for update wait 10即10s超时， 因为 10s大于当前的_enqueue_deadlock_time_sec设置值(9s)，所以Process A就会做死锁检测。 但是可以看到这里死锁检测时间为6s 而不是我们指定_enqueue_deadlock_scan_secs的4s 。   通过反复的测试可以发现，实际的死锁检测时间总是_enqueue_deadlock_scan_secs指定的值向上取整为3的倍数。   总结： enqueue lock队列锁的死锁检测遵循以下原则 1. 默认情况下死锁检测deadlock detection总是3s发生一次， 但是实际受到参数_enqueue_deadlock_scan_secs(deadlock scan interval)的控制，该参数默认为0，死锁检测时间总是_enqueue_deadlock_scan_secs指定的值向上取整为3的倍数， 当_enqueue_deadlock_scan_secs=0 则为3s一次， 当_enqueue_deadlock_scan_secs=4则为6s一次，依此类推。 2. 死锁检测还受到_enqueue_deadlock_time_sec(requests with timeout <= this will not have deadlock detection)的影响，若enqueue request timeout< _enqueue_deadlock_time_sec(默认值为5)，则Server process不会做死锁检测。若enqueue request timeout>_enqueue_deadlock_time_sec 则会参考_enqueue_deadlock_scan_secs定期做死锁检测， 当然request timeout的指定不限于select for update wait [TIMEOUT]一种。   补充：   实际在10.2.0.1中尚未引入以上的这2个hidden parameter ， 大约在patchset 10.2.0.3开始引入了 _enqueue_deadlock_time_sec， 在patchset 10.2.0.5中开始引入了_enqueue_deadlock_scan_secs。   有同学指出RAC中的死锁检测默认应当为10s， 这受到隐藏参数_lm_dd_interval(dd time interval in seconds) ，该参数最早在版本8.0.6中引入。 通过实验可以验证这位同学的说法，我也表示支持，  在10g中该参数默认为60s，从11g开始默认减少到10s。  需要注意的是在11g之前_lm_dd_interval这个参数指定值是不可信任的，这是因为在11g中对LMD进程的死锁检测进行了优化，原本在节点数量较多的RAC中LMD的Deadlock Detection可能消耗更多的CPU，以下是11g中Oracle内部研发Team测试的LMD在多节点情况下的CPU使用情况：  

    我们进一步来了解11g中LMD检测死锁的细节，这里我们会用到11g特有的 UTS TRACE 来获取更多 DD的信息：    

SQL> select * from v$version;

BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
PL/SQL Release 11.2.0.3.0 - Production
CORE    11.2.0.3.0      Production
TNS for Linux: Version 11.2.0.3.0 - Production
NLSRTL Version 11.2.0.3.0 - Production

SQL>
SQL> select * from global_name
  2  ;

GLOBAL_NAME
--------------------------------------------------------------------------------
www.oracledatabase12g.com 

SQL> alter system set "_lm_dd_interval"=20 scope=spfile;

System altered.

SQL> startup force;
ORACLE instance started.

Total System Global Area 1570009088 bytes
Fixed Size                  2228704 bytes
Variable Size            1325403680 bytes
Database Buffers          234881024 bytes
Redo Buffers                7495680 bytes
Database mounted.
Database opened.

SQL> set linesize 140 pagesize 1400
SQL> show parameter lm_dd

NAME                                 TYPE                             VALUE
------------------------------------ -------------------------------- ------------------------------
_lm_dd_interval                      integer                          20

SQL> select count(*) from gv$instance;

  COUNT(*)
----------
         2

instance 1:
SQL> oradebug setorapid 12
Oracle pid: 12, Unix process pid: 8608, image: oracle@vrh2.oracle.com (LMD0)

对 LMD0进程做 UTS TRACE所有RAC相关的内部操作将无所遁形
SQL> oradebug event 10046 trace name context forever,level 8:10708 trace name context forever,level 103: trace[rac.*] disk high;
Statement processed.

Elapsed: 00:00:00.00

SQL> update maclean1 set t1=t1+1;

1 row updated.

instance 2:

SQL> update maclean2 set t1=t1+1;

1 row updated.

SQL> update maclean1 set t1=t1+1;

Instance 1:

SQL> update maclean2 set t1=t1+1;
update maclean2 set t1=t1+1
       *
ERROR at line 1:
ORA-00060: deadlock detected while waiting for resource

Elapsed: 00:00:20.51

LMD0进程的UTS TRACE

2012-06-12 22:27:00.929284 : [kjmpbmsg:process][type 22][msg 0x7fa620ac85a8][from 1][seq 8148.0][len 192]
2012-06-12 22:27:00.929346 : [kjmxmpm][type 22][seq 0.0][msg 0x7fa620ac85a8][from 1]

*** 2012-06-12 22:27:00.929

* kjddind: received DDIND msg with subtype x6

*          reqp->dd_master_inst_kjxmddi == 1

* kjddind: dump sgh:
2012-06-12 22:27:00.929346*: kjddind: req->timestamp [0.15], kjddt [0.13]
2012-06-12 22:27:00.929346*: >> DDmsg:KJX_DD_REMOTE,TS[0.15],Inst 1->2,ddxid[id1,id2,inst:2097153,31,1],ddlock[0x95023930,829],ddMasterInst 1
2012-06-12 22:27:00.929346*: lock [0x95023930,829], op = [mast]
2012-06-12 22:27:00.929346*: reqp->timestamp [0.15], kjddt [0.13]
2012-06-12 22:27:00.929346*: kjddind: updated local timestamp [0.15]

* kjddind: case KJX_DD_REMOTE
2012-06-12 22:27:00.929346*: ADD IO NODE WFG: 0 frame pointer
2012-06-12 22:27:00.929346*: PUSH: type=res, enqueue(0xffffffff.0xffffffff)=0xbbb9af40, block=KJUSEREX, snode=1
2012-06-12 22:27:00.929346*: PROCESS: type=res, enqueue(0xffffffff.0xffffffff)=0xbbb9af40, block=KJUSEREX, snode=1
2012-06-12 22:27:00.929346*: POP: type=res, enqueue(0xffffffff.0xffffffff)=0xbbb9af40, block=KJUSEREX, snode=1
2012-06-12 22:27:00.929346*: kjddopr[TX 0xe000c.0x32][ext 0x5,0x0]: blocking lock 0xbbb9a800, owner 2097154 of inst 2
2012-06-12 22:27:00.929346*: PUSH: type=txn, enqueue(0xffffffff.0xffffffff)=0xbbb9a800, block=KJUSEREX, snode=1
2012-06-12 22:27:00.929346*: PROCESS: type=txn, enqueue(0xffffffff.0xffffffff)=0xbbb9a800, block=KJUSEREX, snode=1
2012-06-12 22:27:00.929346*: ADD NODE TO WFG: type=txn, enqueue(0xffffffff.0xffffffff)=0xbbb9a800, block=KJUSEREX, snode=1
2012-06-12 22:27:00.929346*: POP: type=txn, enqueue(0xffffffff.0xffffffff)=0xbbb9a800, block=KJUSEREX, snode=1
2012-06-12 22:27:00.929346*: kjddopt: converting lock 0xbbce92f8 on 'TX' 0x80016.0x5d4,txid [2097154,34]of inst 2
2012-06-12 22:27:00.929346*: PUSH: type=res, enqueue(0xffffffff.0xffffffff)=0xbbce92f8, block=KJUSEREX, snode=1
2012-06-12 22:27:00.929346*: PROCESS: type=res, enqueue(0xffffffff.0xffffffff)=0xbbce92f8, block=KJUSEREX, snode=1
2012-06-12 22:27:00.929346*: ADD NODE TO WFG: type=res, enqueue(0xffffffff.0xffffffff)=0xbbce92f8, block=KJUSEREX, snode=1
2012-06-12 22:27:00.929855 : GSIPC:AMBUF: rcv buff 0x7fa620aa8cd8, pool rcvbuf, rqlen 1102
2012-06-12 22:27:00.929878 : GSIPC:GPBMSG: new bmsg 0x7fa620aa8d48 mb 0x7fa620aa8cd8 msg 0x7fa620aa8d68 mlen 192 dest x100 flushsz -1
2012-06-12 22:27:00.929878*: << DDmsg:KJX_DD_REMOTE,TS[0.15],Inst 2->1,ddxid[id1,id2,inst:2097153,31,1],ddlock[0x95023930,829],ddMasterInst 1
2012-06-12 22:27:00.929878*: lock [0xbbce92f8,287], op = [mast]
2012-06-12 22:27:00.929878*: ADD IO NODE WFG: 0 frame pointer
2012-06-12 22:27:00.929923 : [kjmpbmsg:compl][msg 0x7fa620ac8588][typ p][nmsgs 1][qtime 0][ptime 0]
2012-06-12 22:27:00.929947 : GSIPC:PBAT: flush start. flag 0x79 end 0 inc 4.4
2012-06-12 22:27:00.929963 : GSIPC:PBAT: send bmsg 0x7fa620aa8d48 blen 224 dest 1.0
2012-06-12 22:27:00.929979 : GSIPC:SNDQ: enq msg 0x7fa620aa8d48, type 65521 seq 8325, inst 1, receiver 0, queued 1
012-06-12 22:27:00.929979 : GSIPC:SNDQ: enq msg 0x7fa620aa8d48, type 65521 seq 8325, inst 1, receiver 0, queued 1
2012-06-12 22:27:00.929996 : GSIPC:BSEND: flushing sndq 0xb491dd28, id 0, dcx 0xbc517770, inst 1, rcvr 0  qlen 0 1
2012-06-12 22:27:00.930014 : GSIPC:BSEND: no batch1 msg 0x7fa620aa8d48 type 65521 len 224 dest (1:0)
2012-06-12 22:27:00.930088 : kjbsentscn[0x0.3f72dc][to 1]
2012-06-12 22:27:00.930144 : GSIPC:SENDM: send msg 0x7fa620aa8d48 dest x10000 seq 8325 type 65521 tkts x1 mlen xe00110
2012-06-12 22:27:00.930531 : GSIPC:KSXPCB: msg 0x7fa620aa8d48 status 30, type 65521, dest 1, rcvr 0
WAIT #0: nam='ges remote message' ela= 1372 waittime=80 loop=0 p3=74 obj#=-1 tim=1339554420931640
2012-06-12 22:27:00.931728 : GSIPC:RCVD: ksxp msg 0x7fa620af6490 sndr 1 seq 0.8149 type 65521 tkts 1
2012-06-12 22:27:00.931746 : GSIPC:RCVD: watq msg 0x7fa620af6490 sndr 1, seq 8149, type 65521, tkts 1
2012-06-12 22:27:00.931763 : GSIPC:RCVD: seq update (0.8148)->(0.8149) tp -15 fg 0x4 from 1 pbattr 0x0
2012-06-12 22:27:00.931779 : GSIPC:TKT: collect msg 0x7fa620af6490 from 1 for rcvr 0, tickets 1
2012-06-12 22:27:00.931794 : kjbrcvdscn[0x0.3f72dc][from 1][idx 2012-06-12 22:27:00.931810 : kjbrcvdscn[no bscn dd_master_inst_kjxmddi == 1

* kjddind: dump sgh:
NXTIN (nil) 0 wq 0 cvtops x0  0x0.0x0(ext 0x0,0x0)[0000-0000-00000000] inst 1
BLOCKER 0xbbb9a800 5 wq 1 cvtops x28 TX 0xe000c.0x32(ext 0x5,0x0)[20000-0002-00000022] inst 2
BLOCKED 0xbbce92f8 5 wq 2 cvtops x1 TX 0x80016.0x5d4(ext 0x2,0x0)[20000-0002-00000022] inst 2
NXTOUT (nil) 0 wq 0 cvtops x0  0x0.0x0(ext 0x0,0x0)[0000-0000-00000000] inst 1
2012-06-12 22:27:00.932058*: kjddind: req->timestamp [0.15], kjddt [0.15]
2012-06-12 22:27:00.932058*: >> DDmsg:KJX_DD_VALIDATE,TS[0.15],Inst 1->2,ddxid[id1,id2,inst:2097153,31,1],ddlock[0x95023930,829],ddMasterInst 1
2012-06-12 22:27:00.932058*: lock [(nil),0], op = [vald_dd]
2012-06-12 22:27:00.932058*: kjddind: updated local timestamp [0.15]

* kjddind: case KJX_DD_VALIDATE

*** 2012-06-12 22:27:00.932

* kjddvald called: kjxmddi stuff:

*                  cont_lockp (nil)

*                  dd_lockp 0x95023930

*                  dd_inst 1

*                  dd_master_inst 1

* sgh graph:
NXTIN (nil) 0 wq 0 cvtops x0  0x0.0x0(ext 0x0,0x0)[0000-0000-00000000] inst 1
BLOCKER 0xbbb9a800 5 wq 1 cvtops x28 TX 0xe000c.0x32(ext 0x5,0x0)[20000-0002-00000022] inst 2
BLOCKED 0xbbce92f8 5 wq 2 cvtops x1 TX 0x80016.0x5d4(ext 0x2,0x0)[20000-0002-00000022] inst 2
NXTOUT (nil) 0 wq 0 cvtops x0  0x0.0x0(ext 0x0,0x0)[0000-0000-00000000] inst 1
POP WFG NODE: lock=(nil)

* kjddvald: dump the PRQ:
BLOCKER 0xbbb9a800 5 wq 1 cvtops x28 TX 0xe000c.0x32(ext 0x5,0x0)[20000-0002-00000022] inst 2
BLOCKED 0xbbce92f8 5 wq 2 cvtops x1 TX 0x80016.0x5d4(ext 0x2,0x0)[20000-0002-00000022] inst 2

* kjddvald: KJDD_NXTONOD ->node_kjddsg.dinst_kjddnd =1

* kjddvald: ... which is not my node, my subgraph is validated but the cycle is not complete
Global blockers dump start:---------------------------------
DUMP LOCAL BLOCKER/HOLDER: block level 5 res [0x80016][0x5d4],[TX][ext 0x2,0x0]
发现dead lock!!!

    可以看到在以上11.2.0.3的测试中 RAC LMD的死锁检测时间确实受到"_lm_dd_interval"参数的影响变成了指定值的20s。  需要注意的是在10g中_lm_dd_interval默认为60s，在节点较少且Processes数不多的环境中这个参数往往是可信的，但是如果节点很多且有大量Server Process则死锁未必能在这60s内检测到。在11g中对该参数(实际优化的是LMD的死锁检测算法)做了充分的优化，一般可以信任其在默认的10s内完成 Enqueue Deadlock Detection。

  在11g中控制 RAC中LMD进程检测死锁的hidden parameter 还不仅于"_lm_dd_interval"这一个，RAC的内部机制永远是一个有意思的话题，但是今天我们就聊到这里:  

SQL> col name for a50
SQL> col describ for a60
SQL> col value for a20
SQL> set linesize 140 pagesize 1400
SQL> SELECT x.ksppinm NAME, y.ksppstvl VALUE, x.ksppdesc describ
  2   FROM SYS.x$ksppi x, SYS.x$ksppcv y
  3   WHERE x.inst_id = USERENV ('Instance')
  4   AND y.inst_id = USERENV ('Instance')
  5   AND x.indx = y.indx
  6  AND x.ksppinm like '_lm_dd%';

NAME                                               VALUE                DESCRIB
-------------------------------------------------- -------------------- ------------------------------------------------------------
_lm_dd_interval                                    20                   dd time interval in seconds
_lm_dd_scan_interval                               5                    dd scan interval in seconds
_lm_dd_search_cnt                                  3                    number of dd search per token get
_lm_dd_max_search_time                             180                  max dd search time per token
_lm_dd_maxdump                                     50                   max number of locks to be dumped during dd validation
_lm_dd_ignore_nodd                                 FALSE                if TRUE nodeadlockwait/nodeadlockblock options are ignored

6 rows selected.