核心系统的节点宕机，居然是 SQL 子游标过多导致，子游标与实例宕机会有什么关系？我们应该如何发现他们之间的关系？
今天我们邀请了云和恩墨的高级技术专家李轶楠，且看他如何抽丝剥茧，层层深入发现线索，并逐步还原犯罪场景，找出真实原因。
以下是分享正文：
大家好，我是云和恩墨的李轶楠，不过网上的朋友更习惯叫我 600，所以我也慢慢熟悉了这个称呼，其实这个称呼来自于 ITPUB 论坛上当时我注册的论坛 ID是“ORA-600”。
闲话不多说，我们来看看我们今天要分享的主题吧，这些年我们积累了大量的客户群体，也意味着我们面对着各种复杂的环境与事件，后续我会把我们小伙伴们所遭遇到的各种或者经典、或者灵异、或者有趣的 CASE ，逐一做成案件分析来分享给大家，希望大家喜欢。
今天就以去年我们所遇到的一次 RAC 节点宕机的故障作为开场吧。
1
案情描述
2015 年 6 月的一个傍晚，大雨滂沱，正坐在家里发呆中，突然被一阵铃声惊醒。
拿起电话，发现是客户来电，于是赶紧接听：
“我们的核心系统在晚上 9 点多突然有一个节点挂了，实例自动重启。虽然没有影响业务，但这种无缘无故的重启发生在核心系统上，直接威胁我们的业务运行，领导很重视，所以今天必须把原因找到，多晚都要给出结果，拜托了！”
2
案情分析
听到客户的描述，心里第一个反应是：还好，只是单节点重启，问题本身应该不严重，至少对业务影响并不大，看来这大雨天是不用淋雨去客户现场了... 呵呵，小心思而已。
客户目前急需的是快速给出问题的原因，以便根据情况作出后续的规避措施，所以需要尽快拿到现场的一些数据来做分析，毕竟分析所需要的信息数据距离故障时间越近，精准度就越高，越有利分析。
经过进一步的沟通，得到了一些案发时的基本信息：
重启的是整个数据库架构的 2 节点，这个库是核心系统，晚上也有业务；
重启实例的情况其实以前也发生过，只不过发生的不多；（潜台词是也许这不是个案，以前的重启意味着可能这个问题一直存在）
当前数据库版本为 11.2.0.1。（看到每个大版本的第一个小版本，总是觉得这种系统会 BUG 缠身...虽然夸大了点，但我们确实遇到了不少这种小版本的 BUG）
当然，很明显只听客户描述是不够的。于是，我远程登录了客户的服务器，开始做进一步检查。
在开始分析之前，先跟大家及一下故障分析的常规思路，也便于初学者在遇到问题的时候知道从何处入手。
在遇到故障时，首先要辨识一下当前的场景主要是性能问题的还是真的故障；
如果是性能问题，那就需要收集当时的系统性能信息与数据库性能信息，AWR、ASH，或者系统的 nmon、top 之类都可以；
如果是故障，那就要检查数据库的告警日志与跟踪文件了，非常典型的就是 alertSID.log，这里面往往给了我们进一步追踪痕迹的指引。除此之外，各个进程的 trace 文件，ASM 的 trace 文件以及 RAC 的各种 log、trace 文件都会给出一些故障的原因或者印记，具体的这些文件所在目录大家都应该熟悉，最典型的就是通过 background_dump_dest、user_dump_dest 参数去查找（注意，RAC 的 log 和 trace 文件与数据库的目录并不在一起，可以检查 $GRID_HOME/log/
的各个子目录），更详细的在这里就不再展开了。
另外，当遭遇这些问题的时候，如果有 MOS 账号的话，建议首先去 MOS 中查看是否有故障相关的 BUG 或者技术文章，这既是快速诊断问题、解决问题的途径，也是 DBA 快速成长的重要手段。
好吧，回到我们的案例中：
1、下面是节点 2 的 Alert Log 部分内容：
在告警日志中我们发现一个很明显的 ORA-600 错误，同时也发现一些其他的 ORA 报错，见上面标红部分。于是我们对这些错误分别进行了分析，发现：
1.1
ORA-600 [kksfbc-wrong-kkscsflgs] (Doc ID 970885.1) 确实是一个 BUG ，在 MOS 上有说明：
但 MOS 上并未说明该 BUG 会导致实例宕机，这个 600 错误看来应该与此次重启关系不大，好吧，作为一个问题记下来就是了。
1.2
在故障时间点，LMHB 进程 Check 发现 mmon 进程阻塞了 LCK0 进程，超过 70s，因此尝试 Kill MMON 进程，该进程被 Kill 之后将会自动重启。
可以看到在 Jun 26 21:51:06 时间点，MMON 进程重启完成。
这里在插播一件事，正好就在前几天，我们的客户也遇到了 MMON 进程的相关问题，在这也顺便分享给大家：客户的 MMON 进程被 Kill 之后并未自动启动，导致 AWR 等性能信息无法自动收集，因此客户希望能够在不启动数据库的情况下启动 MMON ，再想了各种办法之后，最终找到了方法：
或者
大家也可以搜寻一下 MOS 上的文章，看到相关的信息：文档 ID 2023652.1
接下来，在 Jun 26 21:54:10，LMS1 进程报错无法获得latch（object queue header operation）超过 85 秒。
注: LMHB 是 Lock Manager Heartbeat 的缩写。
LMHB 是 11gR2 中引入的后台进程，官方文档介绍是 Global Cache/Enqueue Service Heartbeat Monitor，Monitor the heartbeat of LMON, LMD, and LMSn processes，LMHB monitors LMON, LMD, and LMSn processes to ensure they are running normally without blocking or spinning。
该进程负责监控 LMON、LMD、LMSn 等 RAC 关键的后台进程，保证这些 background process 不被阻塞或 spin 。
2、整理时间线索
为了更清楚的理清线索，我们根据节点 2 的 alert log 信息，整理出如下的时间线点：
从最后的信息可以看出，在 21:54:20 时间点，LMHB 进程强行终止了数据库实例。而终止实例的原因是 LMHB 进程发现 LCK0 进行 Hang 住了，而且超过了 70s 。
在从前面的信息也可以看出，实际上在 21:54:10 时间点，LCK0 进程就已经没有活动了了，而且在该时间点 LMS1 进程也一直在等待 Latch。
很明显，如果 LMS1 进程无法正常工作，Oracle 为了保证集群数据的一致性，为了避免脑裂，必将问题节点强行驱逐重启。
那么 LMS1 在等什么呢？LCK0 为什么被 Hang 住了？
3、LMS1 进程的情况
让我们来看看 LMS1 到底在干什么？
检查
orcl2_lmhb_29939_i204142.trc，而该 Trace 文件产生的时间点是：Jun 26 21:54:10：
从 LMS1 进程的信息来看，LMS1 进程所等待的资源（object queue header operation）正被 ospid=29987 持有，那么 29987 又是什么呢？
4、进一步分析下 ospid=29987 是什么？
让我们接着往下看：
orapid=21，是 Dbw2 进程，即数据库写进程。
最后一句很明显的告诉我们，29987 原来就是 LCK0 进程。这意味着 LMS1 进程所等待的资源正被 LCK0 进程所持有。而同时还有另外一个进程 orapid=21 也在等待该进程。
通过分析我们分析发现：
注：这里解释一下，Orapid 是 Oracle 中的进程 ID，而 Pid 则是 OS 上的进程 ID。所以 Orapid=21 从 v$process 中可以查到是 Dbw2，而 Orapid=14 是 Lms1。
5、继续分析
从数据库 alert log 来看，在 Jun 26 21:54:10 有提示 LCK0 进程已经超过 85 秒没有响应
根据时间点来计算，大概在 Jun 26 21:52:45 点左右开始，LCK0 进程即没有响应了。
那么很明显，我们只要知道 LCK0 进程为什么会 Hang，就知道了此次故障的原因。
那么我们来看看 LCK0 的 Trace 文件，看能不能看到一些线索。
6、LCK0 进程的 Trace 信息
从上述 LCK0 进程的几个时间点的信息来看，第一个时间点 21:50:29 ：Wchan 为 Semtim 。
Wchan 表示进程 Sleeping 的等待表现形式。Semtim 表示在该时间点，LCK0 进程一直处于 Sleep 状态。所谓的 Sleep 状态，是进程持有的资源是不会释放的。
而在第 2 个时间点 21:54:18，LCK0 进程的 Wchan 状态是？这表示未知，如果是为空，则表示该进程处理 Running 状态。
在 21：50 到 21：52 时间段内，LCK0 进程仍然没有恢复正常。那么 LCK0 到底被什么阻塞了（或者说它需要的资源被谁占用了）？
同时也可以看到内存和 Swap 都空闲很多，CPU 也并不忙。
7、继续检查 Trace
在 21：50 时间点我们发现，LCK0 进程是被 MMON 进程锁阻塞了
从上面的 Trace 可以看到之前一直被等待的 993cfec60 资源（Child Object Queue Header Operation）正被 MMON 进程持有。
21:50:29 的时候 LCK0 在等待 MMON 释放资源，而此时 MMON 出现异常，因此在 21:51:06 MMON 进程被 LMHB 强制重启。
然后在重启后，由于 MMON 的异常，导致 21:54:18 该资源仍无法被 LCK0 进程正常持有，最终导致 21:54:20 LMHB 进程强制重启了整个实例。
因此，最终的罪魁祸首是 MMON 进程。
MMON 进程 Oracle 是用于进行 AWR 信息收集的。既然案情发生的原因与它有关，那么接下来的分析自然是查看它的相关 Trace 了。
8、检查 MMON 的相关 Trace
在这里我们可以看到 MMON 进程负责处理对象的统计信息。
从 Trace 中可以看到大量的 Cursor 包含了太多的子游标，例如：
类似上面的信息非常多。很明显，上述 Parent Cursor 包含了大量的子游标，这是为什么在 20 点- 21 点（节点 2 还未重启前的时段）的 AWR 报告中出现大量 Cursor : mutex S 的原因，如下是这个时段的等待事件：
在 MMON 正常通过内部 SQL 收集系统信息时，根本不应该出现这种情况，而此时 MMON 进程却出现异常，这个异常看来应该是与 Cursor 子游标过多有关了。
9、得出结论
最后数据库实例被强行终止的原因是 LCK0 进程出现异常致 LMHB 进程强行终止 Instance 。
在最后 Instance 终止之前的 Diag Dump 中，LCK0 进程的状态仍然是 Hang 的状态，同时也阻塞了 3 个其他 Session，如下：
对于数据库进程，如果状态不是 Dead，而是 Busy，而且持有 Latch 不释放，那么这意味着该进程已被挂起，LCK0 持有的 Latch 是 Object Queue Header Operation。
Oracle MOS 文档也有关于该 Event 的描述如下：Scans of the Object Queue in the buffer cache can hold the “Object Queue Header Operation object queue header operation”。
基于上述的分析，我们最终判断，LCK0 进程出现问题的原因与 Cursor 子游标过多有关。
同时，这又与在 11.2.0.1 版本上的 Child Cursor 总数阀值限制过高有关（实际在版本 10g 中就引入了该 Cursor Obsolescence 游标废弃特性，10g 的 Child Cursor 的总数阀值是 1024，即子游标超过 1024 即被过期，但是这个阀值在 11g 的初期版本中被移除了。）
这就导致出现一个父游标下大量 Child Cursor 即 High Version Count 的发生；由此引发了一系列的版本 11.2.0.3 之前的 Cursor Sharing 性能问题。
这意味着版本 11.2.0.1 和 11.2.0.2 的数据库，将可能出现大量的 Cursor : Mutex S 和 Library Cache Lock 等待事件这种症状，进而诱发其他故障的发生。
因此， 强烈建议 11.2.0.3 以下的版本应尽快将数据库版本升级到 11.2.0.3 以上（11.2.0.3 中默认就有“
_cursor_obsolete_threshold”了，而且默认值为 100），或者通过 _cursor_features_enabled 和 106001 Event 来强制控制子游标过多的情况。
3
结案陈词
该案例的分析还是有些曲折，因为常见导致单节点故障最常见的情况主要是心跳、节点资源之类，而该案例的诱发原因相对有些诡异，先是出现了ORA-600 错误，然后又报了 Kill MMON 的信息，这都让案情分析有些扑朔迷离，当然，最终我们还是找出了问题的主要根源。
通过该起案件我们发现：
1、数据库版本的选择绝对是影响系统稳定性的关键要点；
2、不要以为性能问题只是影响用户体验，有些性能问题是会诱发系统一系列问题的；
3、问题的分析不要想当然，通过 Trace 逐步递进，结合原理与经验，才能更为准确的确定问题；
4、子游标过多千万不能小视，最好能找出根源并解决它，如果确实不好解决，那么可通过设置隐含参数 _cursor_features_enabled 和 106001 Event 强制失效子游标的方式来防止子游标过多的情况，操作如下：
正常重启数据库即可。
往期技术分享：
【预告】2016 年 6 月 16 日，青云QingCloud 将携手业内知名企业在上海静安区新闸路 1438 号八舍咖啡举办以中国零售业转型之技术路径为主题的线下沙龙。
名额有限，报名请扫码下方二维码。
- FIN -
