Know more about Enqueue Deadlock Detection
- by Liu Maclean(???)
??? 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: [email protected] (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.
