诡异的ORA-27090: Unable to reserve kernel resources for asynchronous disk I/O

今年以来,公司多套RAC数据库(版本:11.2.0.4)ASM实例频繁报出ORA-27090: Unable to reserve kernel resources for asynchronous disk I/O错误。这些数据库早在2016年时印象中便出现了此类报错,并且报错并非单个数据库偶发现象,而是大面积爆发,从3月至今仍然有些许数据库会抛出零星错误出现。

什么是ORA-27090?<参考 Doc ID 579108.1 >文中提到,此类报错的原因是操作系统异步IO请求参数 aio-max-nr 过低并且需要调整并发未完成的异步请求数目,避免异步IO请求失败的情况, Oracle官方文档中的建议值如下:

The "aio-max-nr" kernel limit is too low.
io_setup(4096, 0x66e1588) = -1 EAGAIN (Resource temporarily unavailable),

但是很诡异的是,我们的数据库早在2016年左右(第一次触发此问题)时,已经将该参数调整至4194304,理论上是不应该触发异步IO不足的问题。并且此报错风险性较高,ASM实例异步IO失败会导致数据库面临crash问风险,例如DBWR将脏块落盘(数据文件)时,如果此时DBWR进程无法进行时,数据库崩溃等其他异常行为会有极大可能性的。虽然可以将systcl.conf中的aio-max-nr一直调大,但是总归不是长久之计,并且在某年某月时会再次“爆发”。

最可怕的是,通过分析alert中的trace文件时,并没有发现任何有价值信息,所有的线索就是异步IO请求超过最大限制,导致某些IO请求失败抛出错误。。。

通过查看cat /proc/sys/fs/aio-nr查看当前的异步IO请求数量,此值偶尔下降但总量一直处于增长态势, 此时严重怀疑是否数据库中有某些进程执行异步IO请求后并没有释放IO描述符?造成异步IO描述符泄露?

我们数据库集群后发现异步IO请求变回归到正常范围内,但是态势仍然处于上升趋势:

ora11g@travelskydba-rac$ cat /proc/sys/fs/aio-nr 
22784

所以此方法只能短暂”缓解”问题,而并不能实际解决问题,aio-nr 参数依然会持续膨胀。目前此问题已经陷入僵局,随后请硬件同事一同帮忙分析,看看能否打开突破口;提供了一台测试库,硬件同事非常非常给力,部署了如下脚本,测试一下功能,如果OK后就上生产抓一下哪些操作请求占用了大量的请求。

probe syscall.io_setup {
  printf("%d AIO events requested by PID %d (%s)\n", maxevents, pid(), cmdline_str());
}
probe syscall.io_destroy {
  printf("%s AIO events destroy by PID %d (%s)\n", name, pid(), cmdline_str());
}

然而,在测试库中发现了如下现象:

Pass 1: parsed user script and 107 library script(s) using 206820virt/34600res/3196shr/31876data kb, in 240usr/10sys/253real ms.
Pass 2: analyzed script: 3 probe(s), 13 function(s), 76 embed(s), 0 global(s) using 238120virt/66972res/4272shr/63176data kb, in 590usr/170sys/758real ms.
Pass 3: using cached /root/.systemtap/cache/0d/stap_0dc197ff0c82725cac9c1e55fbd4d619_51245.c
Pass 4: using cached /root/.systemtap/cache/0d/stap_0dc197ff0c82725cac9c1e55fbd4d619_51245.ko
Pass 5: starting run.
128 AIO events requested by PID 20479 (oracletestdb1 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq))))
128 AIO events requested by PID 948 (/opt/app/11.2.0/grid/bin/osysmond.bin)
128 AIO events requested by PID 22092 (ora_pz99_testdb1)
128 AIO events requested by PID 22968 (asm_m000_+ASM1)
128 AIO events requested by PID 22972 (asm_m001_+ASM1)

/opt/app/11.2.0/grid/bin/osysmond.bin(CHM特性 Oracle Cluster Health Monitor,具体描述详见 MOS:1328466.1)进程经常会出现在回显中,因为我们已经部署了OSWATCHER,所以集群的CHM健康检查特性是很少使用的,抱着试一试的心态来关闭CHM特性来观察一下AIO数量是否下降

ora11g@travelskydba$ cat /proc/sys/fs/aio-nr
4844416
ora11g@travelskydba$ cat /proc/sys/fs/aio-max-nr
4915200
[grid@travelskydba ~]$ crsctl stop res ora.crf -init
CRS-2673: Attempting to stop 'ora.crf' on 'travelskydba-rac'
CRS-2677: Stop of 'ora.crf' on 'travelskydba-rac' succeeded

grid@travelskydba ~]$ cat /proc/sys/fs/aio-nr 数量由4844416降至36864
36864

现在真相算是“大白”了,原来是CHM健康检查组件占据了异步IO请求且不释放,应该是Bug无疑了,但是在mos上并未找到类似的Bug描述,也许是我们这些库是首发,简单记录下,供大家参考。