Parallel file allocation slowness on ASM even after applying patch 13253549 (Doc ID 1916340.1)

Last updated on FEBRUARY 14, 2019

Applies to:

Symptoms

While doing restore through rman with multiple channels ,it was running too slow.
While creating file ,there was a contention while doing allocation at USD metadata level.

User=0x4486b9fe0 Session=0x4486b9fe0 ReferenceCount=1 Flags=PNC/[0002]
SavepointNum=1a
LibraryHandle: Address=0x459f77468 Hash=2daa4743 LockMode=N PinMode=S
LoadLockMode=0 Status=VALD
ObjectName: Name=SYS.X$DBMS_BACKUP_RESTORE <<--------------------------
FullHashValue=63ebb5dec03eecd8c6ee543b2daa4743 Namespace=BODY(02)
Type=PACKAGE BODY(11) Identifier=0 OwnerIdn=2147483644
Statistics: InvalidationCount=0 ExecutionCount=9001 LoadCount=1
ActiveLocks=17 TotalLockCount=66 TotalPinCount=10566
Counters: BrokenCount=1 RevocablePointer=1 KeepDependency=0

From system state dump and hanganalyze we can see,

Chain 1:
------------------------------------------------------------------------------
-
Oracle session identified by:
{
instance: 3 (+asm.+asm3)
os id: 16897
process id: 27, oracle@test (TNS V1-V3)
session id: 1675
session serial #: 55167
}
is waiting for 'buffer busy' with wait info:
{
p1: 'group#'=0x6
p2: 'obj#'=0x8
p3: 'block#'=0xb4
time in wait: 0.262223 sec
timeout after: 1.737777 sec
wait id: 429997
blocking: 0 sessions
current sql: <none>
short stack:
ksedsts()+465<-ksdxfstk()+32<-ksdxcb()+1927<-sspuser()+112<-__sighandler()<-se
mtimedop()+10<-skgpwwait()+160<-ksliwat()+2022<-kslwaitctx()+163<-kfcWaitForBu
fferPriv()+1199<-kfcGetPin()+3938<-kfcGet0()+7000<-kfcGet1Priv()+1526<-kfcGetP
riv()+900<-kfdusGet()+362<-kffGetUsdFromSrd()+153<-kffIxAddXmap()+3213<-kffFdA
ddImap()+1839<-kffFdAddMap()+479<-kffFileResize()+6627<-kffFileCreate()+5544<-
kffCreate()+868<-kfnsFileCreate()+1500<-kfnDispatch()+694<-opiodr()+917<-ttcpi
p()+2183<-opitsk()+1710<-opiino()+969<-opiodr()+917
wait history:
* time between current wait and wait #1: 0.000000 sec
1. event: 'ASM file metadata operation'
time waited: 0.000216 sec (last interval)
time waited: 151 min 18 sec (total)
wait id: 403164 p1: 'msgop'=0xb
p2: 'locn'=0x1
* time between wait #1 and #2: 0.000000 sec
2. event: 'ges inquiry response'
time waited: 0.000286 sec
wait id: 429996 p1:
'type|mode|where'=0x41440000
p2: 'id1'=0x60016
p3: 'id2'=0x14f59
* time between wait #2 and #3: 0.000000 sec
3. event: 'ASM file metadata operation'
time waited: 0.000254 sec (last interval)
time waited: 151 min 18 sec (total)
wait id: 403164 p1: 'msgop'=0xb
p2: 'locn'=0x1
}
and is blocked by
=> Oracle session identified by:
{
instance: 3 (+asm.+asm3)
os id: 15433
process id: 34, oracle@test (TNS V1-V3)
session id: 2112
session serial #: 28751
}
which is waiting for 'GCS lock esc' with wait info:
{
p1: 'group'=0x6
p2: 'obj#'=0x8
p3: 'block#'=0xb4
time in wait: 0.225440 sec
timeout after: 0.774560 sec
wait id: 16934
blocking: 15 sessions
current sql: <none>
short stack:
ksedsts()+465<-ksdxfstk()+32<-ksdxcb()+1927<-sspuser()+112<-__sighandler()<-se
mtimedop()+10<-skgpwwait()+160<-ksliwat()+2022<-kslwaitctx()+163<-kfcWaitForBu
fferPriv()+1199<-kfcGetPin()+3938<-kfcGet0()+7000<-kfcGet1Priv()+1526<-kfcGetP
riv()+900<-kfdusGet()+362<-kffGetUsdFromSrd()+153<-kffIxAddXmap()+3213<-kffFdA
ddImap()+1839<-kffFdAddMap()+479<-kffFileResize()+6627<-kffFileCreate()+5544<-
kffCreate()+868<-kfnsFileCreate()+1500<-kfnDispatch()+694<-opiodr()+917<-ttcpi
p()+2183<-opitsk()+1710<-opiino()+969<-opiodr()+917
wait history:
* time between current wait and wait #1: 0.000000 sec
1. event: 'ASM file metadata operation'
time waited: 0.000019 sec (last interval)
time waited: 89 min 16 sec (total)
wait id: 125 p1: 'msgop'=0xb
p2: 'locn'=0x1
* time between wait #1 and #2: 0.000000 sec
2. event: 'buffer busy'
time waited: 0.039543 sec
wait id: 16933 p1: 'group#'=0x6
p2: 'obj#'=0x8
p3: 'block#'=0xb4
* time between wait #2 and #3: 0.000000 sec
3. event: 'ASM file metadata operation'
time waited: 0.000351 sec (last interval)
time waited: 89 min 16 sec (total)
wait id: 125 p1: 'msgop'=0xb
p2: 'locn'=0x1
}

Chain 1 Signature: 'GCS lock esc'<='buffer busy'
Chain 1 Signature Hash: 0x118af497
------------------------------------------------------------------------------

It is doing file based allocations.

Changes

Cause

My Oracle Support provides customers with access to over a million knowledge articles and a vibrant support community of peers and Oracle experts.