High CPU usage of foreground process due to OFFLINE ASM Disks (Doc ID 2220752.1)

Last updated on FEBRUARY 07, 2017

Applies to:

Oracle Database - Enterprise Edition - Version 11.2.0.1 to 11.2.0.4 [Release 11.2]
Information in this document applies to any platform.

Symptoms

The following is output to cell alertlog when the ASM disk goes offline

Published: 1 events ASM OFFLINE disk of opcode 5 for diskgroup XXXXX to:

The foreground process of DB instance is using CPU when ASM disk is set to OFFLINE:

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
14249 oracle 20 0 109g 24m 20m R 91.0 0.0 304:53.45 oracle <<<<<<

Call stack of the foreground process (from pstack):

#0 0x00000000094fb8f8 in kslwtbctx ()
#1 0x00000000053e3731 in kfk_reap_ios_from_subsys ()
#2 0x0000000000ce6183 in kfkFDCleanupPriv ()
#3 0x0000000000ce523a in kfkFDCleanup () <<<<<<
#4 0x00000000053ede25 in kfkFDCleanupKsdxCb ()

Trace of the foreground process shows that the file descriptor is being cleaned up:

Received ORADEBUG command (#X) 'CLEANUP_KFK_FD' from process 'Unix
process pid: XXXXX, image: <none>'

However, the following which indicating the completion of cleanup is not in the trace:

Finished processing ORADEBUG command (#X) 'CLEANUP_KFK_FD'

The high wait can also be seen in AWR report:

Event Waits Time Avg(ms) time Wait Class
------------------------------ ------------ ---- ------- ------ ----------
DB CPU 1015 61.8
log file sync 347,500 467. 1 28.4 Commit
cell single block physical rea 146,203 149. 1 9.1 User I/O
kfk: async disk IO 1.150600E+09 72.6 0 4.4 System I/O <<<<<<

You can check the "gc buffer busy acquire" from the information of HANG ANALYSIS.

- dia0 trace
HANG ANALYSIS:
:
Suspected 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
----- ---- -------- ---- ----- ----- ----- ------ ------ -------------------
2 HANG VALID 4 17413 2 2 LOW LOCAL Terminate Process

inst# SessId Ser# OSPID Event
----- ------ ----- --------- -----
4 1608 257 59201 latch: cache buffers chains
4 17413 55785 105526 gc buffer busy acquire <<<<<<
:
-------------------------------------------------------------------------------
Chain 945:
-------------------------------------------------------------------------------
Oracle session identified by:
{
instance: 4
os id: 127287
process id: 2311,
session id: 3365
session serial #: 58735
}
is waiting for 'gc buffer busy acquire' with wait info:
{
p1: 'file#'=0x4d
p2: 'block#'=0x3906b
p3: 'class#'=0x1
time in wait: 0.019508 sec (last interval)
time in wait: 47 min 45 sec (total)
heur. time in wait: 98 min 45 sec <<<<<<

Changes

This may happen when ASM Disk goes OFFLINE.

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