大家好!最近遇到一起数据库hang的故障,将其处理思路分享下。
环境:
操作系统:AIX
数据库版本:12.2
是否RAC:是
分析过程请容我一一道来:
某日,同事反馈数据库节点2有很多cursor:pin S wait on X异常等待事件,与此同时librarycache lock也伴随出现,不过librarycache lock不是一直都存在,查询异常等待事件偶尔出现。这个时候会话开始出现积压,应用反馈应用异常。
登录数据库主机发现节点1正常、节点2一堆的cursor:pin S wait onX,甚至于登录到数据库都很慢,赶紧做了hanganalyze,做完快照之后,开始kill异常等待事件相关的会话进程,但是数据库依旧一大堆cursor等待事件。此时内存接近于耗尽,数据库已处于hang的状态,为了尽快恢复业务,当即对节点2实例进行了重启,重启后恢复正常。
后面同事反映这库节点2之前相同时段出现过很多cursor:pin S wait on X异常等待的情况,过会自动恢复正常了,没有和今天这样数据库hang,当时查到是由于SQL频次突增导致。
1、接下来开始对故障进行分析,我们首先查看hanganalyze日志如下:

发现都是在等待rowcache lock。
2、继续查看堵塞链
Chain1:

从上图我们可以看到Chain1,堵塞源是节点2,SID:1215的会话,此时它堵塞了195个会话,其正在等待cacheid:0X10的ROWCACHE。
Chain2:

接下来分析Chain2,堵塞源是节点2,SID:2419的会话,此时它堵塞了3个会话,其正在等待cacheid:0X10的ROWCACHE。
Chain3:

继续分析Chain3,堵塞源是节点2,SID:6642的会话,此时它堵塞了11个会话,其正在等待cacheid:0X10的ROWCACHE。
Chain4:

以上总结:
从以上的堵塞Chain我们可以看到堵塞源都在等待cacheid:0X10的ROWCACHE。其正在运行的SQL均为查询数据库基表或试图的SQL。并且我们竟然发现在故障时段数据库的自动收集统计信息的JOB在运行,这JOB我们在上线之前就把其调用窗口调整到晚上10点开始,早上6点结束。至于为啥白天会调起,我们后面在另起一篇单独聊聊这事。
3、我们在数据库查了下cacheid:0X10的数据字典缓存,详细如下:

我们从故障时段的AWR也可以看到中这2种ROWCACHE被访问的比较多。

一般对于'RowCache Lock'相关的等待,通常是由于过度的SQL执行解析和sharepool不足导致的。
4、继续分析AWR


从上图我们可以看到SQL运行大部分时间都花在解析上,sharedpool latches上的活动会话占比很高。
正常时段:

故障时段:

查看除了TOP1SQL解析次数在与平时正常相应时段进行比对发现解析次数并没有出现突增的情况。但是图中其他SQL其解析或执行次数都较平时增长不少。
这里就有个疑问了,为啥都是同样的频次突增,为啥之前一下就自动恢复了,这次就hang了呢?
综合以上情况初步确定,由于sharedpool空闲较少,然后应用SQL频次有增加,并且发现部分查询数据字典的SQL出现查询缓慢甚至查不出来的情况,会话积压导致内存不足,此时自动收集统计信息的JOB原本是晚上10点调起的,但是故障时段下午2点也开始调起,成为压死数据库的最后一根稻草。
解决方案:
收集了数据字典的统计信息,将部分查询数据字典的SQL绑定了最优执行计划。并进行了sharedpool的大小调整,在原来的基础上增加了SGA预留的2G,并部署了sharedpool剩余空间的监控,少于500M告警。并要求应用侧整改SQL突增的问题,从目前来看这些方式行之有效,到目前为止数据库再无发生过类似的故障。




