Know more about Enqueue Deadlock Detection

Posted by Liu Maclean(???) on Oracle Blogs See other posts from Oracle Blogs or by Liu Maclean(???)
Published on Sat, 13 Oct 2012 17:25:12 +0000 Indexed on 2012/10/13 21:46 UTC
Read the original article Hit count: 691

Filed under:

??? 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.

© Oracle Blogs or respective owner

Related posts about /Oracle