1 2 Previous Next 19 Replies Latest reply: Nov 6, 2012 6:22 AM by orausern RSS

    Cause of Deadlock

    orausern
      Hi Experts,
      I am on Oracle 11.2.0.2 on Linux. In my database, there is a deadlock reported and I am not able to find out reason for it or even which two different sessions participated in it. Following is the info from the deadlock trace file. I will be thankful for any pointers on the cause of the issue.
       
      *** 2012-10-25 15:38:06.189 
      ENQUEUE DUMP REQUEST: from 2 spnum 12 on [0xa001f][0x33e15],[TX][ext 0x2,0x0] for reason 3 mtype 0 
      DUMP LOCAL BLOCKER/HOLDER: block level 3 res [0xa001f][0x33e15],[TX][ext 0x2,0x0] 
      ----------resource 0xdd61cea0---------------------- 
      resname       : [0xa001f][0x33e15],[TX][ext 0x2,0x0] 
      hash mask     : x3 
      Local inst    : 1 
      dir_inst      : 1 
      master_inst   : 1 
      hv idx        : 8 
      hv last r.inc : 8 
      current inc   : 8 
      hv status     : 0 
      hv master     : 1 
      open options  : dd 
      grant_bits    : KJUSERNL KJUSEREX 
      grant mode    : KJUSERNL  KJUSERCR  KJUSERCW  KJUSERPR  KJUSERPW  KJUSEREX 
      count         : 1         0         0         0         0         1 
      val_state     : KJUSERVS_NOVALUE 
      valblk        : 0x00000000000000000000000000000000 . 
      access_inst   : 1 
      vbreq_state   : 0 
      state         : x0 
      resp          : 0xdd61cea0 
      On Scan_q?    : N 
      Total accesses: 6860 
      Imm.  accesses: 6057 
      Granted_locks : 1 
      Cvting_locks  : 1 
      value_block:  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
      GRANTED_Q : 
      lp 0xcb4fabd0 gl KJUSEREX rp 0xdd61cea0 [0xa001f][0x33e15],[TX][ext 0x2,0x0] 
        master 1 gl owner 0xd4c45958 possible pid 582 xid 77000-0001-00000C6F bast 0 rseq 767 mseq 0 history 0xd497d495 
        open opt KJUSERDEADLOCK   
      CONVERT_Q: 
      lp 0xcc5dae48 gl KJUSERNL rl KJUSERPR rp 0xdd61cea0 [0xa001f][0x33e15],[TX][ext 0x2,0x0] 
        master 1 owner 2  bast 1 rseq 264 mseq 0x1 history 0x77d497ad 
        convert opt KJUSERGETVALUE   
      ----------enqueue 0xcb4fabd0------------------------ 
      lock version     : 535 
      Owner inst       : 1 
      grant_level      : KJUSEREX 
      req_level        : KJUSEREX 
      bast_level       : KJUSERNL 
      notify_func      : (nil) 
      resp             : 0xdd61cea0 
      procp            : 0xdcf1f730 
      pid              : 18995 
      proc version     : 0 
      oprocp           : (nil) 
      opid             : 18995 
      group lock owner : 0xd4c45958 
      possible pid     : 582 
      xid              : 77000-0001-00000C6F 
      dd_time          : 0.0 secs 
      dd_count         : 0 
      timeout          : 0.0 secs 
      On_timer_q?      : N 
      On_dd_q?         : N 
      lock_state       : GRANTED 
      ast_flag         : 0x0 
      Open Options     : KJUSERDEADLOCK 
      Convert options  : KJUSERNOQUEUE KJUSERNODEADLOCKWAIT 
      History          : 0xd497d495 
      Msg_Seq          : 0x0 
      res_seq          : 767 
      valblk           : 0x00000000000000000000000000000000 . 
      user session for deadlock lock 0xcb4fabd0 <----this seems to be the same session as below and I dont see info of any other session 
        sid: 349 ser: 12203 audsid: 102101678 user: 72/PORTALWFN45_ACS 
          flags: (0x41) USR/- flags_idl: (0x1) BSY/-/-/-/-/- 
          flags2: (0x40009) -/-/INC 
        pid: 119 O/S info: user: grid, term: UNKNOWN, ospid: 582 
          image: oracle@cdlt3f002db01 
        client details: 
          O/S info: user: wasadmin, term: unknown, ospid: 1234 
          machine: cdldvjassvap048.nj.adp.com program: JDBC Thin Client 
          application name: JDBC Thin Client, hash value=2546894660 
        current SQL: 
          INSERT INTO ACCESS_CLNT_GRP_XRF (CLNT_OID, GRP_ID, INCLUDED, ADDED_MANUALLY, CREATED_DATE, CREATED_BY) SELECT DISTINCT X.CLNT_OID, X.GRP_OID, :"SYS_B_0" AS INCLUDED, :"SYS_B_1" AS ADDED_MANUALLY, SYSDATE AS CREATED_DATE, :1  AS CREATED_BY  FROM ACCESS_CLNT_GRP_RULE_XRF X WHERE X.GRP_ID = :2  AND NOT EXISTS (SELECT :"SYS_B_2" FROM ACCESS_CLNT_GRP_XRF UG WHERE UG.CLNT_OID= X.CLNT_OID AND UG.GRP_ID= X.GRP_ID) 
      DUMP LOCAL BLOCKER: initiate state dump for DEADLOCK 
        possible owner[119.582] on resource TX-000A001F-00033E15 
      
      *** 2012-10-25 15:38:06.190 
      Submitting asynchronized dump request [28]. summary=[ges process stack dump (kjdglblkrdm1)]. 
      Global blockers dump start:--------------------------------- 
      DUMP LOCAL BLOCKER/HOLDER: block level 3 res [0x170011][0x10ab5],[TX][ext 0x4,0x0] 
      ----------resource 0xda168d40---------------------- 
      resname       : [0x170011][0x10ab5],[TX][ext 0x4,0x0] 
      hash mask     : x3 
      Local inst    : 1 
      dir_inst      : 2 
      master_inst   : 2 
      hv idx        : 26 
      hv last r.inc : 8 
      current inc   : 8 
      hv status     : 0 
      hv master     : 1 
      open options  : dd 
      Held mode     : KJUSERNL 
      Cvt mode      : KJUSERPR 
      Next Cvt mode : KJUSERNL 
      msg_seq       : 0x1 
      res_seq       : 290 
      grant_bits    : KJUSERNL 
      grant mode    : KJUSERNL  KJUSERCR  KJUSERCW  KJUSERPR  KJUSERPW  KJUSEREX 
      count         : 1         0         0         0         0         0 
      val_state     : KJUSERVS_NOVALUE 
      valblk        : 0x70529d50ff7f00000000000000000000 pRP 
      access_inst   : 2 
      vbreq_state   : 0 
      state         : x8 
      resp          : 0xda168d40 
      On Scan_q?    : N 
      Total accesses: 8496 
      Imm.  accesses: 7633 
      Granted_locks : 0 
      Cvting_locks  : 1 
      value_block:  70 52 9d 50 ff 7f 00 00 00 00 00 00 00 00 00 00 
      GRANTED_Q : 
      CONVERT_Q: 
      lp 0xdb922560 gl KJUSERNL rl KJUSERPR rp 0xda168d40 [0x170011][0x10ab5],[TX][ext 0x4,0x0] 
        master 2 gl owner 0xdf73f828 possible pid 582 xid 77000-0001-00000C6F bast 0 rseq 290 mseq 0 history 0x495149da 
        convert opt KJUSERGETVALUE   
      DUMP LOCAL BLOCKER/HOLDER: block level 3 res [0xa001f][0x33e15],[TX][ext 0x2,0x0] 
      ----------resource 0xdd61cea0---------------------- 
      resname       : [0xa001f][0x33e15],[TX][ext 0x2,0x0] 
      hash mask     : x3 
      Local inst    : 1 
      dir_inst      : 1 
      master_inst   : 1 
      hv idx        : 8 
      hv last r.inc : 8 
      current inc   : 8 
      hv status     : 0 
      hv master     : 1 
      open options  : dd 
      grant_bits    : KJUSERNL KJUSEREX 
      grant mode    : KJUSERNL  KJUSERCR  KJUSERCW  KJUSERPR  KJUSERPW  KJUSEREX 
      count         : 1         0         0         0         0         1 
      val_state     : KJUSERVS_NOVALUE 
      valblk        : 0x70529d50ff7f00000000000000000000 pRP 
      access_inst   : 1 
      vbreq_state   : 0 
      state         : x0 
      resp          : 0xdd61cea0 
      On Scan_q?    : N 
      Total accesses: 6862 
      Imm.  accesses: 6058 
      Granted_locks : 1 
      Cvting_locks  : 1 
      value_block:  70 52 9d 50 ff 7f 00 00 00 00 00 00 00 00 00 00 
      GRANTED_Q : 
      lp 0xcb4fabd0 gl KJUSEREX rp 0xdd61cea0 [0xa001f][0x33e15],[TX][ext 0x2,0x0] 
        master 1 gl owner 0xd4c45958 possible pid 582 xid 77000-0001-00000C6F bast 0 rseq 767 mseq 0 history 0xd497d495 
        open opt KJUSERDEADLOCK   
      CONVERT_Q: 
      lp 0xcc5dae48 gl KJUSERNL rl KJUSERPR rp 0xdd61cea0 [0xa001f][0x33e15],[TX][ext 0x2,0x0] 
        master 1 owner 2  bast 1 rseq 264 mseq 0x1 history 0x77d497ad 
        convert opt KJUSERGETVALUE   
      ----------enqueue 0xcb4fabd0------------------------ 
      lock version     : 535 
      Owner inst       : 1 
      grant_level      : KJUSEREX 
      req_level        : KJUSEREX 
      bast_level       : KJUSERNL 
      notify_func      : (nil) 
      resp             : 0xdd61cea0 
      procp            : 0xdcf1f730 
      pid              : 18995 
      proc version     : 0 
      oprocp           : (nil) 
      opid             : 18995 
      group lock owner : 0xd4c45958 
      possible pid     : 582 
      xid              : 77000-0001-00000C6F 
      dd_time          : 0.0 secs 
      dd_count         : 0 
      timeout          : 0.0 secs 
      On_timer_q?      : N 
      On_dd_q?         : N 
      lock_state       : GRANTED 
      ast_flag         : 0x0 
      Open Options     : KJUSERDEADLOCK 
      Convert options  : KJUSERNOQUEUE KJUSERNODEADLOCKWAIT 
      History          : 0xd497d495 
      Msg_Seq          : 0x0 
      res_seq          : 767 
      valblk           : 0x00000000000000003100050200000000 .1 
      user session for deadlock lock 0xcb4fabd0 <----this seems to be the same session as above and I dont see info of any other session 
        sid: 349 ser: 12203 audsid: 102101678 user: 72/PORTALWFN45_ACS 
      
        sid: 349 ser: 12203 audsid: 102101678 user: 72/PORTALWFN45_ACS 
          flags: (0x41) USR/- flags_idl: (0x1) BSY/-/-/-/-/- 
          flags2: (0x40009) -/-/INC 
        pid: 119 O/S info: user: grid, term: UNKNOWN, ospid: 582 
          image: oracle@cdlt3f002db01 
        client details: 
          O/S info: user: wasadmin, term: unknown, ospid: 1234 
          machine: cdldvjassvap048.nj.adp.com program: JDBC Thin Client 
          application name: JDBC Thin Client, hash value=2546894660 
        current SQL: 
        INSERT INTO ACCESS_CLNT_GRP_XRF (CLNT_OID, GRP_ID, INCLUDED, ADDED_MANUALLY, CREATED_DATE, CREATED_BY) SELECT DISTINCT X.CLNT_OID, X.GRP_OID, :"SYS_B_0" AS INCLUDED, :"SYS_B_1" AS ADDED_MANUALLY, SYSDATE AS CREATED_DATE, :1  AS CREATED_BY  FROM ACCESS_CLNT_GRP_RULE_XRF X WHERE X.GRP_ID = :2  AND NOT EXISTS (SELECT :"SYS_B_2" FROM ACCESS_CLNT_GRP_XRF UG WHERE UG.CLNT_OID= X.CLNT_OID AND UG.GRP_ID= X.GRP_ID) 
      DUMP LOCAL BLOCKER: initiate state dump for DEADLOCK 
        possible owner[119.582] on resource TX-000A001F-00033E15 
      
      *** 2012-10-25 15:38:06.191 
      Submitting asynchronized dump request [28]. summary=[ges process stack dump (kjdglblkrdm1)]. 
      Global blockers dump end:----------------------------------- 
      Global Wait-For-Graph(WFG) at ddTS[0.8a] : 
      BLOCKED 0xdb922560 3 wq 2 cvtops x1 TX 0x170011.0x10ab5(ext 0x4,0x0)[77000-0001-00000C6F] inst 1 
      BLOCKER 0xdb339ad0 3 wq 1 cvtops x28 TX 0x170011.0x10ab5(ext 0x4,0x0)[71000-0002-00002D5B] inst 2 
      BLOCKED 0xdb7f3648 3 wq 2 cvtops x1 TX 0xa001f.0x33e15(ext 0x2,0x0)[71000-0002-00002D5B] inst 2 
      BLOCKER 0xcb4fabd0 3 wq 1 cvtops x28 TX 0xa001f.0x33e15(ext 0x2,0x0)[77000-0001-00000C6F] inst 1 
      
      *** 2012-10-25 15:38:07.113 
      * Cancel deadlock victim lockp 0xdb922560 
      2012-10-25 17:26:16.039638 : Setting 3-way CR grants to 0 global-lru off? 0 
      
      *** 2012-10-25 17:27:49.961 
      2012-10-25 17:27:49.961892 : Setting 3-way CR grants to 1 global-lru off? 0 
      2012-10-25 17:52:42.505182 : Setting 3-way CR grants to 1 global-lru off? 0 
      * received DRM start msg from 2 (cnt 1, last 1, rmno 50) 
      
      *** 2012-10-25 19:16:31.443 
      Rcvd DRM(50) AFFINITY Transfer pkey 88431.0 from 1 to 2 oscan 1.1 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.32/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.33/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.33/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.33/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.37/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.32/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.33/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.33/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.33/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      2012-10-25 19:16:31.687987 : 
      End DRM(50) for pkey transfer request(s) from 2 
      stale cvak(res) fr 2:0xdfff5898([0x1978f378][0x8fba1c6e],[LB][ext 0x0,0x0])[h=KJUSERNL,n=KJUSEREX,b=KJUSERNL,ls=KJUSERSTAT_NOVALUE]mseq:0x10003(msg),0x0(resp)rseq:0x416(msg),0x417(resp) 
      
      *** 2012-10-25 22:06:03.671 
      ----------resource 0xdfff5898---------------------- 
      resname       : [0x1978f378][0x8fba1c6e],[LB][ext 0x0,0x0] 
      hash mask     : x3 
      Local inst    : 1 
      dir_inst      : 2 
      master_inst   : 2 
      hv idx        : 50 
      hv last r.inc : 8 
      current inc   : 8 
      hv status     : 0 
      hv master     : 1 
      open options  : dd 
      Held mode     : KJUSERNL 
      Cvt mode      : KJUSERPR 
      Next Cvt mode : KJUSERNL 
      msg_seq       : (nil) 
      res_seq       : 1047 
      grant_bits    : KJUSERNL 
      grant mode    : KJUSERNL  KJUSERCR  KJUSERCW  KJUSERPR  KJUSERPW  KJUSEREX 
      count         : 1         0         0         0         0         0 
      val_state     : KJUSERVS_NOVALUE 
      valblk        : 0x94160ec3eccc040094160ec3eccc0400 . 
      access_inst   : 2 
      vbreq_state   : 0 
      state         : x4 
      resp          : 0xdfff5898 
      On Scan_q?    : N 
      Total accesses: 13084 
      Imm.  accesses: 11996 
      Granted_locks : 0 
      Cvting_locks  : 1 
      value_block:  94 16 0e c3 ec cc 04 00 94 16 0e c3 ec cc 04 00 
      GRANTED_Q : 
      CONVERT_Q: 
      lp 0xdb6588d0 gl KJUSERNL rl KJUSERPR rp 0xdfff5898 [0x1978f378][0x8fba1c6e],[LB][ext 0x0,0x0] 
        master 2 gl owner 0xdc5d6240 possible pid 6224 xid 4B000-0001-000012F8 bast 0 rseq 1047 mseq 0 history 0x495149da 
        convert opt   
      MSG [16:KJX_CONV_AST_IND] [0x1978f378][0x8fba1c6e],[LB][ext 0x0,0x0] RMno=65706 inc=8 len=112 sender=(2,2) seq=0 
           fg=p stat=KJUSERSTAT_NOVALUE spnum=12 flg=x0 
          flow ctrl: ver=8 flag=161 len=112 tkts=0 seq=0 wrp=0 
                     sndr=2 dest=1 rcvr=0 
           rseq x416 mseq x10003 copts x1 hl 5 cl 0 nl 0 
           valblk 0x01000000815f93600000000000000000 ._` 
      stale cvak(res) fr 2:0xdfff5898([0x1978f378][0x8fba1c6e],[LB][ext 0x0,0x0])[h=KJUSERNL,n=KJUSEREX,b=KJUSERPR,ls=KJUSERSTAT_NOVALUE]mseq:0x10004(msg),0x0(resp)rseq:0x416(msg),0x417(resp) 
      ----------resource 0xdfff5898---------------------- 
      resname       : [0x1978f378][0x8fba1c6e],[LB][ext 0x0,0x0] 
      hash mask     : x3 
      Local inst    : 1 
      dir_inst      : 2 
      master_inst   : 2 
      hv idx        : 50 
      hv last r.inc : 8 
      current inc   : 8 
      hv status     : 0 
      hv master     : 1 
      open options  : dd 
      Held mode     : KJUSERNL 
      Cvt mode      : KJUSERPR 
      Next Cvt mode : KJUSERNL 
      msg_seq       : (nil) 
      res_seq       : 1047 
      grant_bits    : KJUSERNL 
      grant mode    : KJUSERNL  KJUSERCR  KJUSERCW  KJUSERPR  KJUSERPW  KJUSEREX 
      count         : 1         0         0         0         0         0 
      val_state     : KJUSERVS_NOVALUE 
      valblk        : 0x24000000000000000008000000000000 $ 
      access_inst   : 2 
      vbreq_state   : 0 
      state         : x4 
      resp          : 0xdfff5898 
      On Scan_q?    : N 
      Total accesses: 13085 
      Imm.  accesses: 11997 
      Granted_locks : 0 
      Cvting_locks  : 1 
      value_block:  24 00 00 00 00 00 00 00 00 08 00 00 00 00 00 00 
      GRANTED_Q : 
      CONVERT_Q: 
      lp 0xdb6588d0 gl KJUSERNL rl KJUSERPR rp 0xdfff5898 [0x1978f378][0x8fba1c6e],[LB][ext 0x0,0x0] 
        master 2 gl owner 0xdc5d6240 possible pid 6224 xid 4B000-0001-000012F8 bast 0 rseq 1047 mseq 0 history 0x495149da 
        convert opt   
      MSG [16:KJX_CONV_AST_IND] [0x1978f378][0x8fba1c6e],[LB][ext 0x0,0x0] RMno=3 inc=8 len=112 sender=(2,2) seq=0 
           fg=p stat=KJUSERSTAT_NOVALUE spnum=12 flg=xc 
          flow ctrl: ver=-106 flag=161 len=112 tkts=0 seq=0 wrp=0 
                     sndr=2 dest=1 rcvr=0 
           rseq x416 mseq x10004 copts x0 hl 5 cl 0 nl 3 
           valblk 0x0000000000a907006800000000000000 .h 
      kjddt2vb: valblk  [0.8c] > local ts [0.8b] 
      
      *** 2012-10-25 22:16:54.817 
      Begin DRM(51) (swin 0) - AFFINITY transfer pkey 88431.0 to 1 oscan 0.1 
      kjiobjscn 1 
      ftd (30) received from node 2 (8 0.0/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (33) received from node 2 (8 0.32/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (37) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (30) received from node 2 (8 0.30/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (33) received from node 2 (8 0.34/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (30) received from node 2 (8 0.30/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (33) received from node 2 (8 0.34/0.0) 
      all ftds received 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.37/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.34/0.0) 
      all ftds received 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.37/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.34/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.34/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.30/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (33) received from node 2 (8 0.34/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.30/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (33) received from node 2 (8 0.34/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      2012-10-25 22:16:55.112752 : 
      
      * End DRM for pkey remastering request(s) (locally requested) 
      
      *** 2012-10-25 22:22:35.175 
      2012-10-25 22:22:35.175781 : Setting 3-way CR grants to 0 global-lru off? 0 
      
      *** 2012-10-25 22:24:09.000 
      2012-10-25 22:24:09.000900 : Setting 3-way CR grants to 1 global-lru off? 0 
      2012-10-25 22:29:20.348861 : Setting 3-way CR grants to 1 global-lru off? 0 
      2012-10-25 23:15:02.016255 : Setting 3-way CR grants to 0 global-lru off? 0 
      
      *** 2012-10-25 23:16:05.212 
      2012-10-25 23:16:05.212156 : Setting 3-way CR grants to 1 global-lru off? 0 
      
      *** 2012-10-25 23:16:36.041 
      2012-10-25 23:16:36.041650 : Setting 3-way CR grants to 0 global-lru off? 0 
      
      *** 2012-10-25 23:18:10.146 
      2012-10-25 23:18:10.146473 : Setting 3-way CR grants to 1 global-lru off? 0 
      
      *** 2012-10-25 23:23:24.514 
      2012-10-25 23:23:24.514488 : Setting 3-way CR grants to 0 global-lru off? 0 
      
      *** 2012-10-25 23:24:26.699 
      2012-10-25 23:24:26.699355 : Setting 3-way CR grants to 1 global-lru off? 0 
      2012-10-25 23:32:11.212627 : Setting 3-way CR grants to 0 global-lru off? 0 
      
      *** 2012-10-25 23:33:13.028 
      2012-10-25 23:33:13.028646 : Setting 3-way CR grants to 1 global-lru off? 0 
      
      *** 2012-10-25 23:36:22.121 
      2012-10-25 23:36:22.121783 : Setting 3-way CR grants to 0 global-lru off? 0 
      
      *** 2012-10-25 23:36:58.785 
      * received DRM start msg from 2 (cnt 1, last 1, rmno 52) 
      Rcvd DRM(52) AFFINITY Transfer pkey 88431.0 from 1 to 2 oscan 1.1 
      
      *** 2012-10-25 23:36:58.875 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.33/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.37/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.33/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.32/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.33/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.33/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.33/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.32/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.32/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      2012-10-25 23:36:59.124760 : 
      End DRM(52) for pkey transfer request(s) from 2 
      
      *** 2012-10-25 23:38:26.130 
      2012-10-25 23:38:26.130755 : Setting 3-way CR grants to 1 global-lru off? 0 
      2012-10-25 23:58:38.071978 : Setting 3-way CR grants to 0 global-lru off? 0 
      
      *** 2012-10-26 00:00:44.096 
      2012-10-26 00:00:44.096005 : Setting 3-way CR grants to 1 global-lru off? 0 
      
      *** 2012-10-26 00:04:22.583 
      2012-10-26 00:04:22.583348 : Setting 3-way CR grants to 0 global-lru off? 0 
      
      *** 2012-10-26 00:08:31.315 
      2012-10-26 00:08:31.315412 : Setting 3-way CR grants to 1 global-lru off? 0 
      2012-10-26 00:20:57.846700 : Setting 3-way CR grants to 0 global-lru off? 0 
      
      *** 2012-10-26 00:25:05.085 
      2012-10-26 00:25:05.085042 : Setting 3-way CR grants to 1 global-lru off? 0 
      2012-10-26 00:44:17.764966 : Setting 3-way CR grants to 0 global-lru off? 0 
      
      *** 2012-10-26 00:48:25.602 
      2012-10-26 00:48:25.602491 : Setting 3-way CR grants to 1 global-lru off? 0 
      2012-10-26 01:14:50.222098 : Setting 3-way CR grants to 0 global-lru off? 0 
      
      *** 2012-10-26 01:19:00.590 
      2012-10-26 01:19:00.590826 : Setting 3-way CR grants to 1 global-lru off? 0 
      2012-10-26 02:44:09.453387 : Setting 3-way CR grants to 0 global-lru off? 0 
      
      *** 2012-10-26 02:49:19.105 
      2012-10-26 02:49:19.105284 : Setting 3-way CR grants to 1 global-lru off? 0 
      2012-10-26 02:59:41.444548 : Setting 3-way CR grants to 0 global-lru off? 0 
      
      *** 2012-10-26 03:02:47.808 
      2012-10-26 03:02:47.808071 : Setting 3-way CR grants to 1 global-lru off? 0 
      
      *** 2012-10-26 03:05:22.310 
      2012-10-26 03:05:22.310631 : Setting 3-way CR grants to 0 global-lru off? 0 
      
      *** 2012-10-26 03:07:16.408 
      * received DRM start msg from 2 (cnt 2, last 1, rmno 53) 
      Rcvd DRM(53) AFFINITY Transfer pkey 74335.0 from 1 to 2 oscan 1.1 
      Rcvd DRM(53) AFFINITY Transfer pkey 88398.0 from 1 to 2 oscan 1.1 
      ftd (30) received from node 2 (8 0.0/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (33) received from node 2 (8 0.32/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.33/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.33/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.33/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.33/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.33/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.33/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      ftd (30) received from node 2 (8 0.31/0.0) 
      all ftds received 
      ftd (33) received from node 2 (8 0.33/0.0) 
      all ftds received 
      
      * kjxftdn: break from kjxftdn, post lmon later 
      ftd (35) received from node 2 (8 0.36/0.0) 
      all ftds received 
      ftd (37) received from node 2 (8 0.38/0.0) 
      all ftds received 
      2012-10-26 03:07:16.718164 : 
      End DRM(53) for pkey transfer request(s) from 2 
      
      *** 2012-10-26 03:11:35.100 
      2012-10-26 03:11:35.100544 : Setting 3-way CR grants to 1 global-lru off? 0 
      2012-10-26 03:44:44.666224 : Setting 3-way CR grants to 0 global-lru off? 0 
      2012-10-26 04:00:49.272473 : Setting 3-way CR grants to 1 global-lru off? 0 
      
      *** 2012-10-26 04:08:35.037 
      2012-10-26 04:08:35.037716 : Setting 3-way CR grants to 0 global-lru off? 0 
      
      *** 2012-10-26 04:11:41.226 
      2012-10-26 04:11:41.226172 : Setting 3-way CR grants to 1 global-lru off? 0 
        • 1. Re: Cause of Deadlock
          Osama_Mustafa
          Oracle Solve Deadlock by its own self
          • 2. Re: Cause of Deadlock
            orausern
            >
            Oracle Solve Deadlock by its own self
            >
            Yes! But it will also run into the same issues again and again unless the issue is identified and resolved. For that reason I want to find what could have caused the deadlock. But from the deadlock file, I am not able to make out the reason.

            Thanks,
            • 3. Re: Cause of Deadlock
              Osama_Mustafa
                client details: 
                  O/S info: user: wasadmin, term: unknown, ospid: 1234 
                  machine: cdldvjassvap048.nj.adp.com program: JDBC Thin Client 
                  application name: JDBC Thin Client, hash value=2546894660 
                current SQL: 
                  INSERT INTO ACCESS_CLNT_GRP_XRF (CLNT_OID, GRP_ID, INCLUDED, ADDED_MANUALLY, CREATED_DATE, CREATED_BY) SELECT DISTINCT X.CLNT_OID, X.GRP_OID, :"SYS_B_0" AS INCLUDED, :"SYS_B_1" AS ADDED_MANUALLY, SYSDATE AS CREATED_DATE, :1  AS CREATED_BY  FROM ACCESS_CLNT_GRP_RULE_XRF X WHERE X.GRP_ID = :2  AND NOT EXISTS (SELECT :"SYS_B_2" FROM ACCESS_CLNT_GRP_XRF UG WHERE UG.CLNT_OID= X.CLNT_OID AND UG.GRP_ID= X.GRP_ID) 
              DUMP LOCAL BLOCKER: initiate state dump for DEADLOCK 
                possible owner[119.582] on resource TX-000A001F-00033E15 
              Check from this user wasadmin and insert clause , your application caused this deadlock
              • 4. Re: Cause of Deadlock
                orausern
                Yes true! I could make out that this one sql is involved in the deadlock. But my question and doubt here is that, just one session by itself can not cause deadlock right? For deadlock there has to be two sessions whereas here I dont' see two different sessions. So how can a single session cause deadlock?

                Thanks,
                • 5. Re: Cause of Deadlock
                  Dom Brooks
                  BLOCKED 0xdb922560 3 wq 2 cvtops x1 TX 0x170011.0x10ab5(ext 0x4,0x0)[77000-0001-00000C6F] inst 1 
                  BLOCKER 0xdb339ad0 3 wq 1 cvtops x28 TX 0x170011.0x10ab5(ext 0x4,0x0)[71000-0002-00002D5B] inst 2 
                  BLOCKED 0xdb7f3648 3 wq 2 cvtops x1 TX 0xa001f.0x33e15(ext 0x2,0x0)[71000-0002-00002D5B] inst 2 
                  BLOCKER 0xcb4fabd0 3 wq 1 cvtops x28 TX
                  Lock mode in WFG is column 3. Interpret using:
                  #define KJUSERNL 0         /* no permissions */   (Null)  
                  #define KJUSERCR 1         /* concurrent read */ (Row-S (SS))  
                  #define KJUSERCW 2         /* concurrent write */ (Row-X (SX))  
                  #define KJUSERPR 3         /* protected read */    (Share)  
                  #define KJUSERPW 4         /* protected write */ (S/Row-X (SSX))  
                  #define KJUSEREX 5         /* exclusive access */ (Exclusive) 
                  These are mode 4 (S) TX locks which can have a few causes, including ITLs, unique indexes and bitmap indexes.
                  • 6. Re: Cause of Deadlock
                    Osama_Mustafa
                    Yes , But as i told you before seems application Need to be monitor again
                    • 7. Re: Cause of Deadlock
                      Jonathan Lewis
                      orausern wrote:
                      Yes true! I could make out that this one sql is involved in the deadlock. But my question and doubt here is that, just one session by itself can not cause deadlock right? For deadlock there has to be two sessions whereas here I dont' see two different sessions. So how can a single session cause deadlock?
                      You're running RAC - the other session is in the other instance, but presumably it survived the deadlock collision and the application response left you with no other information.

                      The deadlock is between tx/6 and tx/4 - and since the SQL we see in this trace is for an insert, it's possible that it's a problem relating to conflict on unique (or bitmap) index entries. (Generally tx/4 is something to do with indexes, although there are a couple of exotic causes that relate to internal activity.)

                      The tx/6 tx/4 show up in some of the detail in the granted_q and convert_q:
                      GRANTED_Q : 
                      lp 0xcb4fabd0 gl KJUSEREX rp 0xdd61cea0 [0xa001f][0x33e15],[TX][ext 0x2,0x0] 
                        master 1 gl owner 0xd4c45958 possible pid 582 xid 77000-0001-00000C6F bast 0 rseq 767 mseq 0 history 0xd497d495 
                        open opt KJUSERDEADLOCK   
                      CONVERT_Q: 
                      lp 0xcc5dae48 gl KJUSERNL rl KJUSERPR rp 0xdd61cea0 [0xa001f][0x33e15],[TX][ext 0x2,0x0] 
                        master 1 owner 2  bast 1 rseq 264 mseq 0x1 history 0x77d497ad 
                        convert opt KJUSERGETVALUE   
                      Note the granted_q has KJUSEREX (exclusive / 6)
                      and the convert_q has KJUSERPR (protected read / 4)

                      Look initially for code that generates values which might allow for duplicates to appear in different instances. Bear in mind, though, that it might be something to do with anomalies in referential integrity such as child rows being inserted in one instance for parent rows that have been inserted, but not yet committed in the other instance.

                      Regards
                      Jonathan Lewis
                      • 8. Re: Cause of Deadlock
                        orausern
                        Thanks a lot Jonathan! I can confirm that there are no ref. key on the related tables. the strange thing is I see only one session here. I have pasted the ENTIRE relevant portion of the trace file. If there is a deadlock, will there not be TWO sessions? Here I see one only - but I have only very basic knowledge on deadlocks and none in interpreting deadlock trace files!
                        • 9. Re: Cause of Deadlock
                          Dom Brooks
                          If you're licensed for Diagnostic pack, you could use Active Session History (ASH) to see if you can get some more information about the deadlock participants.

                          Deadlock detection kicks in on about 3 seconds.
                          The in-memory ASH buffer, exposed via (G)V$ACTIVE_SESSION_HISTORY (GV for RAC obviously), samples all sessions actively working or actively waiting every second so you might well get some valuable additional information from across the cluster.

                          This ASH buffer has a limited lifespan before the active sessions from once every 10 seconds are stored down in the ASH repository - DBA_HIST_ACTIVE_SESS_HISTORY. So you have to then be a bit lucky to get anything about the deadlock situation.
                          • 10. Re: Cause of Deadlock
                            Mohamed Houri
                             If there is a deadlock, will there not be TWO sessions?
                            It is not necessary to have two differents sessions in order to produce a deadlock. Think about a single session using autonomous transaction. It is easy then to produce a deadlock within this single session (but two differents transactions)
                            create table t1
                             (col1 number primary key);
                            
                            create table t2
                             (col1    number primary key
                             ,status  varchar2(12) not null
                             ,col2    number
                             ,col2v   number generated always as (case when status = 'ACTIVE' then col2 end) VIRTUAL
                              ,constraint t2_fk foreign key (col2v) references t1(col1)
                              ,constraint t2_ck check (status in ('ACTIVE','INACTIVE') and (status = 'INACTIVE'
                             or col2 is not null))
                             );
                             
                            insert into t1
                            select rownum
                            from dual
                            connect by level <=100;
                             
                            commit;
                             
                            insert into t2 (col1, status, col2) values (1, 'ACTIVE',50);
                             
                            declare
                            pragma autonomous_transaction;
                            begin
                              delete from t1
                              where col1 = 99;
                              commit;
                            end;
                            /
                             
                            ORA-00060: deadlock detected while waiting for resource
                            ORA-06512: at line 4
                            00060. 00000 -  "deadlock detected while waiting for resource";
                            *Cause:    Transactions deadlocked one another while waiting for resources.
                            *Action:   Look at the trace file to see the transactions and resources
                                       involved. Retry if necessary.
                             
                            Best regards

                            Mohamed Houri
                            www.hourim.wordpress.com
                            • 11. Re: Cause of Deadlock
                              sb92075
                              ORA-00060 deposits many useful details in the alert_SID.log file.

                              please post these details for us to review.
                              • 12. Re: Cause of Deadlock
                                orausern
                                @Mohamed:
                                Thank you very much!! I wasn't aware at all of this possibility and will expore this in more detail. One thing though - the moment we remove the Ref. Constraint , the dead lock goes away - I ran your code in my 11.2.0.2 db, got deadlock, removed the Ref. Key constraint and it went fine. Now it is absolute certain that in this table where I got deadlock there is no foreign key. So may be other factors are in play here! But thanks for the insight on autonomous txn possibility. I know that our batch pl/sql programs have this autonomous txns and that may have something to do!
                                @sb92075
                                Yes I missed to post it! Alert log has this info:
                                Global Enqueue Services Deadlock detected. More info in file /oracle/diag/rdbms/db01/db0101/trace/db01_lmd01_18994.trc
                                • 13. Re: Cause of Deadlock
                                  sb92075
                                  orausern wrote:
                                  @Mohamed:
                                  Thank you very much!! I wasn't aware at all of this possibility and will expore this in more detail. One thing though - the moment we remove the Ref. Constraint , the dead lock goes away - I ran your code in my 11.2.0.2 db, got deadlock, removed the Ref. Key constraint and it went fine. Now it is absolute certain that in this table where I got deadlock there is no foreign key. So may be other factors are in play here! But thanks for the insight on autonomous txn possibility. I know that our batch pl/sql programs have this autonomous txns and that may have something to do!
                                  @sb92075
                                  Yes I missed to post it! Alert log has this info:
                                  There are more details in alert_SID.log file itself.

                                  Be sure that the FK constraint has an actual INDEX on the appropriate column(s) otherwise whole table can be locked!
                                  • 14. Re: Cause of Deadlock
                                    orausern
                                    >
                                    Be sure that the FK constraint has an actual INDEX on the appropriate column(s) otherwise whole table can be locked!
                                    >

                                    In my previous reply I was referring to the example that Howri gave on how a single session can cause deadlock...in the actual deadlock situatiion for which I asked the question, there is no foreign key involved. Also alert log has only this one line:
                                    Global Enqueue Services Deadlock detected. More info in file...
                                    Thanks again!!,
                                    1 2 Previous Next