Self deadlock while running DDL
(Doc ID 2658435.1)
Last updated on JULY 18, 2023
Applies to:
Oracle Database - Enterprise Edition - Version 19.4.0.0.0 and laterInformation in this document applies to any platform.
Symptoms
While running DDL , it was hitting dead-lock .
2020-02-21T14:46:24.772897+01:00
Errors in file /u01/app/oracle/diag/rdbms/xxxxxxxx1/xxxxxxxx11/trace/xxxxxxxx11_dia0_237158.trc (incident=9533189):
ORA-32701: Possible hangs up to hang ID=89 detected
Incident details in: /u01/app/oracle/diag/rdbms/xxxxxxxx1/xxxxxxxx11/incident/incdir_9533189/xxxxxxxx11_dia0_237158_i9533189.trc
2020-02-21T14:46:29.496062+01:00
DIA0 terminating blocker (ospid: 296612 sid: 409 ser#: 3553) of hang with ID = 88
requested by master DIA0 process on instance 2
Hang Resolution Reason: Although the number of affected sessions did not
justify automatic hang resolution initially, this previously ignored
hang was automatically resolved.
by terminating session sid:409 with serial # 3553 (ospid:296612)
KILL SESSION for sid=(409, 3553):
Reason = hang manager
Mode = KILL HARD SAFE -/-/-
Requestor = DIA0 (orapid = 22, ospid = 237158, inst = 1)
Owner = Process: USER (orapid = 442, ospid = 296612)
Result = ORA-0
DIA0 successfully terminated session sid:409 with serial # 3553 (ospid:296612) with status 0.
2020-02-21T14:46:47.563879+01:00
JIT: pid 349381 requesting full stop
2020-02-21T15:15:29.990915+01:00
Thread 1 advanced to log sequence 24828 (LGWR switch)
Current log# 10 seq# 24828 mem# 0: +DATAC1/xxxxxxxx1/ONLINELOG/group_10.543.991408397
Current log# 10 seq# 24828 mem# 1: +RECOC1/xxxxxxxx1/ONLINELOG/group_10.5140.1015754429
File_name:: alert_xxxxxxxx11.log
user session for deadlock lock 0xb9eaadba68
sid: 409 ser: 3553 audsid: 448833965 user: 839/BMW_ADMIN
flags: (0x45) USR/- flags2: (0x48009) -/DDLT2/INC
flags_idl: (0x1) status: BSY/-/-/- kill: -/-/-/-
pid: 442 O/S info: user: oracle, term: UNKNOWN, ospid: 296612
image: oracle@xxxxxxxx01.mmmmm.net
client details:
O/S info: user: *****, term: unknown, ospid: 32812
machine: LP30159 program: SQL Developer
application name: SQL Developer, hash value=1012150930
current SQL: <none: error encountered - unable to get kgl lock no-wait>
*** 2020-02-21T14:33:49.048579+01:00
ERROR: KGL Pin timeout. Handle=0xba72b3efe0
LibraryObjectPin: Address=0xbbd77efe40 Handle=0xba72b3efe0 RequestMode=X
User=0x10c0a823e0 Session=0x10c0a823e0 Count=0 Mask=0000 Flags=[00] SavepointNum=0x3d28
LibraryHandle: Address=0xba72b3efe0 Hash=b5eef4b4 LockMode=X PinMode=S LoadLockMode=0 Status=VALD
ObjectName: Name=BMW_ADMIN.USER_MGMT
FullHashValue=e70a25cd24cde730e8dfefa6b5eef4b4 Namespace=TABLE/PROCEDURE(01) Type=PACKAGE(09) ContainerId=0 ContainerUid=0 Identifier=5048647 OwnerIdn=839
Statistics: InvalidationCount=0 ExecutionCount=0 LoadCount=1 ActiveLocks=2 TotalLockCount=3 TotalPinCount=2
Counters: BrokenCount=1 RevocablePointer=1 KeepDependency=0 Version=0 BucketInUse=1 HandleInUse=1 HandleReferenceCount=0
Concurrency: DependencyMutex=0xba72b3f090(0, 2, 0, 0) Mutex=0xba72b3f130(0, 3062, 0, 0)
Flags=PIN/TIM/[00002801] Flags2=[0000]
WaitersLists:
Lock=0xba72b3f070[0xba72b3f070,0xba72b3f070]
Pin=0xba72b3f050[0xbbd77efe70,0xbbd77efe70]
LoadLock=0xba72b3f0c8[0xba72b3f0c8,0xba72b3f0c8]
Timestamp: Current=10-08-2019 08:53:10
HandleReference: Address=0xba72b3f1d8 Handle=0xbbb9d9aac0 Flags=OWN[200]
LockInstance: id='LBe70a25cd24cde730' GlobalEnqueue=(nil) ReleaseCount=0
PinInstance: id='NBe70a25cd24cde730' GlobalEnqueue=(nil)
LibraryObject: Address=0xb95f1fd8e8 HeapMask=0000-0115-0115-0000 Flags=EXS/LOC[0004] Flags2=/CSC[4000000] Flags3=[0000] PublicFlags=NST[0001]
DataBlocks:
Block: #='0' name=KGLH0^b5eef4b4 pins=0 Change=NONE
Heap=0xba72af29d8 Pointer=0xb95f1fda08 Extent=0xb95f1fd838 Flags=I/-/P/A/-/-/-
FreedLocation=0 Alloc=1.406250 Size=3.976562 LoadTime=15311035723
Block: #='2' name=PLDIA^b5eef4b4 pins=0 Change=NONE
Heap=0xb95f1fdb90 Pointer=0xbccf6c3a78 Extent=0xbccf6c39c8 Flags=I/-/-/A/-/-/-
FreedLocation=0 Alloc=17.031250 Size=19.781250 LoadTime=15311035723
Block: #='4' name=PLMCD^b5eef4b4 pins=1 Change=NONE
Heap=0xb95f1fdc68 Pointer=0xbccf6bea78 Extent=0xbccf6be9c8 Flags=I/-/P/A/-/-/-
FreedLocation=0 Alloc=1.914062 Size=3.937500 LoadTime=15311035733
Block: #='8' name=KGLS^b5eef4b4 pins=1 Change=NONE
Heap=0xb95f1fdd40 Pointer=0xbccf6be910 Extent=0xbccf6bd9c8 Flags=I/-/P/A/-/-/-
FreedLocation=0 Alloc=0.156250 Size=3.937500 LoadTime=15311035733
sid: 409 ser: 3553 audsid: 448833965 user: 839/BMW_ADMIN
flags: (0x45) USR/- flags2: (0x48009) -/DDLT2/INC
flags_idl: (0x1) status: BSY/-/-/- kill: -/-/-/-
pid: 442 O/S info: user: oracle, term: UNKNOWN, ospid: 296612
image: oracle@xxxxxxxx01.mmmmm.net
client details:
O/S info: user: *****, term: unknown, ospid: 32812
machine: LP30159 program: SQL Developer
application name: SQL Developer, hash value=1012150930
current SQL: <none: error encountered - unable to get kgl lock no-wait>
Lock id=LB,0xe70a25cd,0x24cde730
2020-02-21 14:33:49.060*:kjdggblkrdmp(): DUMP LOCAL BLOCKER/HOLDER: block level 0 res [0xe70a25cd][0x24cde730],[LB][ext 0x0,0x0][domid 0x0]
----------resource 0xbd45b0a858----------------------
resname : [0xe70a25cd][0x24cde730],[LB][ext 0x0,0x0][domid 0x0]
lmdid : 2
rht group : 0
rht ptr : 0xbde475fc20
rht bucket idx: 10291
hp : 0xbde55018e8
domain ptr : 0xbdff447818
hash mask : x7
Local inst : 1
dir_inst : 2
master_inst : 2
^^^^^^^^^^^^^^^^^^^^^^^^^^^^
hv idx : 73
hv last r.inc : 78
current inc : 84
hv status : 0
hv master inst: 2
open options : deadlock detection=N, cached=N, varvblk=N, slock=Y
Held mode : KJUSEREX
Cvt mode : KJUSEREX
Next Cvt mode : KJUSERNL
msg_seq : 0x7ffc00010000
res_seq : 195 (0xc3)
grant_bits : KJUSEREX
grant mode : KJUSERNL KJUSERCR KJUSERCW KJUSERPR KJUSERPW KJUSEREX
count : 0 0 0 0 0 1
val_state : KJUSERVS_NOVALUE
valblk : 0x00000000000000000000000000000000 .
access_inst : 1
vbreq_state : 0
state : x0
resp : 0xbd45b0a858
entry : DIR=N, MASTER=N
On Scan_q? : N
On Cache? : N
On Remote_q? : N
history : x0
frozen : 0
Total accesses: 961
Imm. accesses: 741
SbcastID : 0 (0x0)
request uid : 18087937 (0x1140001)
exclusive bit : on
bast instance : 32767
Granted_locks : 1
Cvting_locks : 0
Reqing_locks : none
value_block: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
GRANTED_Q:
lp 0xbbd778f7d0 gl KJUSEREX rp 0xbd45b0a858 [0xe70a25cd][0x24cde730],[LB][ext 0x0,0x0][domid 0x0]
master 2 gl owner 0x1030923490 possible pid 0 xid 1BA000-0001-1000000131 rseq 195 mseq 0 bast none
history NONE > NONE > NONE > NONE > REF_RES > SLK_BLK2 > GR2CVT > SLK_CVGG > LOC_AST
open opt KJUSERDEADLOCK KJUSERCLIENTLOCK flags 0x1 sec since mv2grQ 900
CONVERT_Q:
----------enqueue 0xbbd778f7d0------------------------
lock version : 1
Owner inst : 1
grant_level : KJUSEREX
req_level : KJUSEREX
bast_level : KJUSERNL
notify_func : none
resp : 0xbd45b0a858
procp : 0xbd849e8548
pid : 296612
proc version : 24
oprocp : (nil)
opid : 296612
group lock owner : 0x1030923490
xid : 1BA000-0001-00000131
dd_time : 0.0 secs
dd_count : 0
timeout : 0.0 secs
On_timer_q? : N
On_dd_q? : N
sec since mv2grQ : 900
lock_state : GRANTED
ast_flag : 0x0
flags : 0x1
Open Options : KJUSERDEADLOCK KJUSERCLIENTLOCK
Convert options : KJUSERNOQUEUE KJUSERNODEADLOCKWAIT
History : NONE > NONE > NONE > NONE > REF_RES > SLK_BLK2 > GR2CVT > SLK_CVGG > LOC_AST
Msg_Seq : 0x0
res_seq : 195
valblk : 0x00000000000000001400050400000000 .
Pin id=NB,0xe70a25cd,0x24cde730
2020-02-21 14:33:49.060*:kjdggblkrdmp(): DUMP LOCAL BLOCKER/HOLDER: block level 0 res [0xe70a25cd][0x24cde730],[NB][ext 0x0,0x0][domid 0x0]
----------resource 0xbdc5411ca0----------------------
resname : [0xe70a25cd][0x24cde730],[NB][ext 0x0,0x0][domid 0x0]
lmdid : 1
rht group : 0
rht ptr : 0xbd24cb2c30
rht bucket idx: 11205
hp : 0xbd44f87980
domain ptr : 0xbdff447818
hash mask : x7
Local inst : 1
dir_inst : 4
master_inst : 4
hv idx : 75
hv last r.inc : 84
current inc : 84
hv status : 0
hv master inst: 4
open options : deadlock detection=N, cached=N, varvblk=N, slock=Y
Held mode : KJUSERPR
Cvt mode : KJUSERNL
Next Cvt mode : KJUSERNL
msg_seq : 0x7ffc00000000
res_seq : 170 (0xaa)
grant_bits : KJUSERPR
grant mode : KJUSERNL KJUSERCR KJUSERCW KJUSERPR KJUSERPW KJUSEREX
count : 0 0 0 1 0 0
val_state : KJUSERVS_NOVALUE
valblk : 0x30303134303030353034303030303030 0014000504000000
access_inst : 1
vbreq_state : 0
state : x0
resp : 0xbdc5411ca0
entry : DIR=N, MASTER=N
On Scan_q? : N
On Cache? : N
On Remote_q? : N
history : x0
frozen : 0
Total accesses: 318701
Imm. accesses: 2567
SbcastID : 0 (0x0)
request uid : 0 (0x0)
exclusive bit : off
bast instance : 32767
Granted_locks : 1
Cvting_locks : 0
Reqing_locks : none
value_block: 30 30 31 34 30 30 30 35 30 34 30 30 30 30 30 30
GRANTED_Q:
lp 0xb9eaadba68 gl KJUSERPR rp 0xbdc5411ca0 [0xe70a25cd][0x24cde730],[NB][ext 0x0,0x0][domid 0x0]
master 4 gl owner 0xbe0728eb0 possible pid 296612 xid 1BA000-0001-7FFC00000131 rseq 170 mseq 0 bast none
^^^^^^^^^^^^^^^^^^^^^^^^
history NONE > NONE > NONE > NONE > NONE > NONE > REF_RES > SLK_SCVL > LOC_AST
open opt KJUSERDEADLOCK KJUSERCLIENTLOCK flags 0x1 sec since mv2grQ 901
CONVERT_Q:
----------enqueue 0xb9eaadba68------------------------
lock version : 1
Owner inst : 1
grant_level : KJUSERPR
req_level : KJUSERPR
bast_level : KJUSERNL
notify_func : none
resp : 0xbdc5411ca0
procp : 0xbd849e8548
pid : 296612
proc version : 24
oprocp : (nil)
opid : 296612
group lock owner : 0xbe0728eb0
possible pid : 296612
xid : 1BA000-0001-00000131
dd_time : 0.0 secs
dd_count : 0
timeout : 0.0 secs
On_timer_q? : N
On_dd_q? : N
sec since mv2grQ : 901
lock_state : GRANTED
ast_flag : 0x0
flags : 0x1
Open Options : KJUSERDEADLOCK KJUSERCLIENTLOCK
Convert options : KJUSERTRCCANCEL
History : NONE > NONE > NONE > NONE > NONE > NONE > REF_RES > SLK_SCVL > LOC_AST
Msg_Seq : 0x0
res_seq : 170
valblk : 0x82ff36010000000000000000fc7f0000 .6
kjusuc: caught error=28 resname=[0xe70a25cd][0x24cde730],[NB][ext 0x0,0x0][domid 0x0] esm=0 svr_mode_kjp=0
File_name:: xxxxxxxx11_ora_296612.trc
Node 2,
*** 2020-02-21T14:27:48.171283+01:00
Verified Hangs in the System
Root Chain Total Hang
Hang Hang Inst Root #hung #hung Hang Hang Resolution
ID Type Status Num Sess Sess Sess Conf Span Action
----- ---- -------- ---- ----- ----- ----- ------ ------ -------------------
87 HANG UNRSLVBL 4 2537 2 2 LOW LOCAL LongOpInProgress:PQ
Hang Ignored Reason: This hang involves sessions that are part of a parallel
query. These operations can execute for a long time. If this operation
is actually hung, there are other mechanisms in place to resolve this
type of hang.
Cluster Health global hang metric is not degrading.
Instance Health and User Calls Completed global hang metrics are not degrading.
'Blocked Session' hang metric is not degrading (0x0002000000000000:15)
Hang Priority is 1428 (0x594). Hang Severity is 400 (maximum is 10000)
Inst Sess Ser Proc Wait Wait
Num ID Num OSPID Name Time(s) Event
----- ------ ----- --------- ----- ------- -----
4 3573 48335 397025 FG 149 PX Deq: Execute Reply
4 2537 30126 45422 P03J 185 PX Deq: Table Q Normal
Wait event statistics for event 'PX Deq: Table Q Normal'
Self-Resolved Hang Count : 57
Self-Resolved Hang Total Hang Time in seconds : 9896
Self-Resolved Hang Minimum Hang Time in seconds : 17
Self-Resolved Hang Maximum Hang Time in seconds : 1992
Resolved Hang Count : 0
Total Hung Session Count : 13
Total Wait Time in micro-seconds : 616852060538
Total Wait Count : 127147886
Moving Average of Wait Time in micro-seconds : 1300
Outliers Total Wait Time in micro-seconds : 124621160448
Outliers Total Wait Count : 349
Percentage of Outliers : 0%
Victim Information
Existing or Ignored
HangID Inst# Sessid Ser Num OSPID Fatal BG New Hang Count
------ ----- ------ ------- --------- -------- ------------- -------
82 2 2924 22137 242401 N Existing Hang 1
85 1 409 3553 296612 N Existing Hang 2
86 2 2525 7 54366 N Existing Hang 1
87 4 2537 30126 45422 N New Hang 1
*** 2020-02-21T14:27:48.171607+01:00
Wait-For-Graphs collected at 02/21/20 14:27:45)
===============================================================================
Cycles:
-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
Oracle session identified by:
{
instance: 1 (xxxxxxxx1.xxxxxxxx11)
os id: 296612
process id: 442, oracle@xxxxxxxx01.mmmmm.net
session id: 409
session serial #: 3553
module name: 0 (SQL DeveloperRp02vm (TNS V1-V3)TNS V1-V3))
}
is waiting for 'library cache pin' with wait info:
{
p1: 'handle address'=0xba72b3efe0
p2: 'pin address'=0xbbd77efe40
p3: '100*mode+namespace'=0x4d094700010003
time in wait: 2 min 46 sec (last interval)
time in wait: 8 min 54 sec (total)
timeout after: 6 min 5 sec
wait id: 1399
blocking: 0 sessions
current sql_id: 177758731
wait history:
* time between current wait and wait #1: 0.000000 sec
1. event: 'ges enter server mode'
time waited: 0.000002 sec
wait id: 1418
* time between wait #1 and #2: 0.000000 sec
2. event: 'library cache pin'
time waited: 0.499933 sec (last interval)
time waited: 6 min 7 sec (total)
wait id: 1399 p1: 'handle address'=0xba72b3efe0
p2: 'pin address'=0xbbd77efe40
p3: '100*mode+namespace'=0x4d094700010003
* time between wait #2 and #3: 0.000000 sec
3. event: 'ges enter server mode'
time waited: 0.000046 sec
wait id: 1417
}
and is blocked by the session at the start of the chain.
Chain 1 Signature: 'library cache pin' (cycle)
Chain 1 Signature Hash: 0xa1c76a9b
-------------------------------------------------------------------------------
File_name:: /xxxxxxxx12_dia0_240210_vfy_30.trc
Changes
Cause
To view full details, sign in with your My Oracle Support account. |
|
Don't have a My Oracle Support account? Click to get started! |