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

Last updated on OCTOBER 31, 2016

Applies to:

Oracle Database - Enterprise Edition - Version 11.2.0.4 and later
Information in this document applies to any platform.

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, oracleamrndhl479.pfizer.com (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, oracleamrndhl479.pfizer.com (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.

Cause

Sign In with your My Oracle Support account

Don't have a My Oracle Support account? Click to get started

My Oracle Support provides customers with access to over a
Million Knowledge Articles and hundreds of Community platforms