李轶楠（网名ORA-600）
云和恩墨高级技术专家
本文来自上周四晚云和恩墨大讲堂李轶楠的分享 - 真实案件之意料之外的 RAC 宕机罪犯—子游标。先来看看他是怎么介绍自己的~
“大家好，我是云和恩墨的李轶楠，不过网上的朋友更习惯叫我600，所以我也慢慢熟悉了这个称呼，其实这个称呼来自于ITPUB论坛上当时我注册的论坛ID“ORA-600”，因为这个ID跟Oracle的著名错误号一样，很容易给大家留下深刻印象，所以被我借用了过来，呵呵。这些年通过论坛上认识了很多朋友，也结识了现在与我一起奋战的恩墨小伙伴们。
闲话不多说，我们来看看我们今天要分享的主题吧，这些年我们积累了大量的客户群体，也意味着我们面对着各种复杂的环境与事件，后续我会把我们小伙伴们所遭遇到的各种或者经典、或者灵异、或者有趣的case，逐一做成案件分析来分享给大家，希望大家喜欢。今天就以去年我们所遇到的一次RAC节点宕机的故障作为开场吧。”
1. 案情描述
2015年6月的一个傍晚，大雨滂沱，坐在家里发呆中，突然被一阵铃声惊醒。拿起电话，发现是客户来电，于是赶紧接听：
我们的核心系统在晚上9点多突然有一个节点挂了，实例自动重启。虽然没有影响业务，但这种无缘无故的重启发生在核心系统上，直接威胁我们的业务运行，领导很重视，所以今天必须把原因找到，多晚都要给出结果，拜托了！
2. 案情分析
听到客户的描述，心里第一个反应是：还好，只是单节点重启，问题本身应该不严重，至少对业务影响并不大，看来这大雨天是不用淋雨去客户现场了。。。呵呵，小心思而已。
客户目前急需的是快速给出问题的原因，以便根据情况作出后续的规避措施，所以需要尽快拿到现场的一些数据来做分析，毕竟分析所需要的信息数据距离故障时间越近，精准度就越高，越有利分析。
经过进一步的沟通，得到了一些案发时的基本信息：
1、重启的是整个数据库架构的2节点，这个库是核心系统，晚上也有业务；
2、重启实例的情况其实以前也发生过，只不过发生的不多；（潜台词是也许这不是个案，以前的重启意味着可能这个问题一直存在）
3、 当前数据库版本为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/<hostname> 的各个子目录），更详细的在这里就不再展开了。
另外，当遭遇这些问题的时候，如果有 MOS 账号的话，建议首先去 MOS 中查看是否有故障相关的 BUG 或者技术文章，这既是快速诊断问题、解决问题的途径，也是 DBA 快速成长的重要手段。关于 MOS 的使用，大家可以加公众号“oracle”，在其中可以看到5月5日发的一篇“Oracle 初学者入门指南-什么是 Metalink 或 MOS？”
好吧，回到我们的案例中：
1. 下面是节点2的 alert log 部分内容：
在告警日志中我们发现一个很明显的 ORA-600 错误，同时也发现一些其他的 ORA 报错，见上面标红部分。于是我们对这些错误分别进行了分析，发现：
1）ORA-600 [kksfbc-wrong-kkscsflgs] (Doc ID 970885.1) 确实是一个 bug，在 MOS 上有说明：
但 MOS 上并未说明该 BUG 会导致实例宕机，这个600错误看来应该与此次重启关系不大，好吧，作为一个问题记下来就是了。
2） 在故障时间点，LMHB 进程 check 发现 mmon 进程阻塞了 LCK0 进程，超过 70s，因此尝试 killMMON 进程，该进程被 kill 之后会自动重启。
可以看到在Jun 26 21:51:06 时间点，MMON 进程重启完成。
这里在插播一件事，正好就在前几天，我们的客户也遇到了MMON进程的相关问题，在这也顺便分享给大家：客户的 MMON 进程被Kill之后并未自动启动，导致 AWR 等性能信息无法自动收集，因此客户希望能够在不启动数据库的情况下启动 MMON，再想了各种办法之后，最终找到了方法：
· Restart the database instance
或者
· Set the instance to "restrictedsession" mode and then bring it back to normal mode using followingcommands as SYSDBA:
alter system enable restricted session;
alter system disable restricted session;
大家也可以搜寻一下 MOS 上的文章，看到相关的信息：文档 ID 2023652.1
接下来，在Jun 26 21:54:10，LMS1 进程报错无法获得 latch（objectqueue header operation） 超过85秒。
注: 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 arerunning normally without blocking or spinning。 该进程负责监控 LMON、LMD、LMSn 等 RAC 关键的后台进程，保证这些 background process 不被阻塞或 spin。 LMHB 是LockManager Heartbeat 的缩写。
2. 为了更清楚的理清线索，我们根据节点2的 alert log 信息，整理出如下时间线点：
从最后的信息可以看出，在 21:54:20 时间点，LMHB 进程强行终止了数据库实例. 而终止实例的原因是 LMHB 进程发现 LCK0 进行 hung 住了，而且超过了70s。在从前面的信息也可以看出，实际上在21:54:10时间点，LCK0 进程就已经没有活动了了，而且在该时间点 LMS1 进程也一直在等待latch。很明显，如果 LMS1 进程无法正常工作，Oracle 为了保证集群数据的一致性，为了避免脑裂，必然将问题节点强行驱逐重启。
那么 LMS1 在等什么呢？LCK0 为什么被 Hung 住了？
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 是什么？
让我们接着往下看：
SO: 0x9911283b0, type: 2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3 proc=0x9911283b0, name=process, file=ksu.h LINE:11459, pg=0 (process) Oracle pid:36, ser:2, calls cur/top: 0x9b17e58e0/0x9b17e58e0 flags : (0x6) SYSTEM flags2: (0x0), flags3: (0x0) intr error: 0, call error: 0, sess error: 0, txn error 0 intr queue: empty ksudlp FALSE at location: 0 (post info) last post received: 0 0 35 last post received-location: ksr2.h LINE:603 ID:ksrpublish last process to post me: 981110608 118 0 last post sent: 0 0 36 last post sent-location: ksr2.h LINE:607 ID:ksrmdone last process posted by me: 9911283b0 2 6 (latch info) wait_event=0 bits=20 holding (efd=3) 993cfec60 Child object queue header operation level=5 child#=117 Location from where latch is held: kcl2.h LINE:3966 ID:kclbufs: Context saved from call: 0 state=busy(shared) [value=0x4000000000000001] wlstate=free [value=0] waiters [orapid (seconds since: put on list, posted, alive check)]: 14 (95, 1435326858, 4) 21 (94, 1435326858, 7) waiter count=2 Process Group: DEFAULT, pseudo proc: 0x9b11ca008 O/S info: user: oracle, term: UNKNOWN, ospid: 29987 OSD pid info: Unix process pid: 29987, image: oracle@ebtadbsvr2 (LCK0) |
最后一句很明显的告诉我们，29987 原来就是 LCK0 进程。这意味着 lms1 进程所等待的资源正被 LCK0 进程所持有。而同时还有另外一个进程 orapid=21 也在等待该进程。通过分析我们分析发现：orapid=21，是 dbw2 进程，即数据库写进程。
注：这里解释一下，orapid 是 oracle 中的进程 id，而 pid 则是 os 上的进程 id。所以 orapid=21 从 v$process 中可以查到是 dbw2，而 orapid=14 是 lms1.
5. 从数据库 alert log 来看，在 Jun 26 21:54:10 有提示 lck0 进程已经超过85秒没有响应
LCK0 (ospid: 29987) has not called a wait for 85 secs |
根据时间点来计算，大概在 Jun 26 21:52:45 点左右开始，LCK0 进程即没有响应了。
那么很明显，我们只要知道 LCK0 进程为什么会 hung，就知道了此次故障的根本原因。
那么我们来看看 LCK0 的 trace 文件，看能不能看到一些线索。
6. LCK0 进程的 trace 信息
*** 2015-06-26 21:50:29.329 Process diagnostic dump for oracle@ebtadbsvr2 (LCK0), OS id=29987, pid: 36, proc_ser: 2, sid: 1729, sess_ser: 3 ------------------------------------------------------------------------------- loadavg : 6.47 26.96 34.97 Memory (Avail / Total) = 10598.05M / 64421.55M Swap (Avail / Total) = 20256.00M / 20479.99M F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD 0 S oracle 29987 1 0 76 0 - 10541946 semtim Apr05 ? 01:25:21 ora_lck0_orcl2 Short stack dump: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1782<-sspuser()+112<-__restore_rt()<-semop()+7<-skgpwwait()+156<-kslgess()+1799<-ksl_get_shared_latch()+620<-kclbufs()+272<-kclanticheck()+412<-kclahrt()+88<-ksbcti()+212<-ksbabs()+1732<-kclabs()+186<-ksbrdp()+923<-opirip()+623<-opidrv()+603<-sou2o()+103<-opimai_real()+266<-ssthrdmain()+214<-main()+201<-__libc_start_main()+244<-_start()+36 *** 2015-06-26 21:54:18.438 Process diagnostic dump for oracle@ebtadbsvr2 (LCK0), OS id=29987, pid: 36, proc_ser: 2, sid: 1729, sess_ser: 3 ------------------------------------------------------------------------------- loadavg : 2.04 13.34 27.63 Memory (Avail / Total) = 9519.06M / 64421.55M Swap (Avail / Total) = 20256.00M / 20479.99M F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD 0 R oracle 29987 1 0 85 0 - 10541965 ? Apr05 ? 01:26:55 ora_lck0_orcl2 Short stack dump: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1782<-sspuser()+112<-__restore_rt()<-kcbo_get_next_qheader()+255<-kclbufs()+321<-kcldirtycheck()+231<-kclahrt()+93<-ksbcti()+212<-ksbabs()+1732<-kclabs()+186<-ksbrdp()+923<-opirip()+623<-opidrv()+603<-sou2o()+103<-opimai_real()+266<-ssthrdmain()+214<-main()+201<-__libc_start_main()+244<-_start()+36 |
从上述 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 进程锁阻塞了
SO: 0x9d10f97c0, type: 2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3 proc=0x9d10f97c0, name=process, file=ksu.h LINE:11459, pg=0 (process) Oracle pid:31, ser:1, calls cur/top: 0x965657408/0x9b17e3f18 flags : (0x2) SYSTEM flags2: (0x20), flags3: (0x0) intr error: 0, call error: 0, sess error: 0, txn error 0 intr queue: empty ksudlp FALSE at location: 0 (post info) last post received: 0 0 35 last post received-location: ksr2.h LINE:603 ID:ksrpublish last process to post me: 9911283b0 2 6 last post sent: 0 0 26 last post sent-location: ksa2.h LINE:282 ID:ksasnd last process posted by me: 9911283b0 2 6 (latch info) wait_event=0 bits=26 holding (efd=7) 993cfec60 Child object queue header operation level=5 child#=117 Location from where latch is held: kcbo.h LINE:884 ID:kcbo_link_q: Context saved from call: 0 state=busy(exclusive) [value=0x200000000000001f, holder orapid=31] wlstate=free [value=0] waiters [orapid (seconds since: put on list, posted, alive check)]: 36 (82, 1435326627, 1) 21 (81, 1435326627, 1) waiter count=2 holding (efd=7) 9b5a5d630 Child cache buffers lru chain level=2 child#=233 Location from where latch is held: kcb2.h LINE:3601 ID:kcbzgws: Context saved from call: 0 state=busy [holder orapid=31] wlstate=free [value=0] holding (efd=7) 9c2a99938 Child cache buffers chains level=1 child#=27857 Location from where latch is held: kcb2.h LINE:3214 ID:kcbgtcr: fast path (cr pin): Context saved from call: 12583184 state=busy(exclusive) [value=0x200000000000001f, holder orapid=31] wlstate=free [value=0] Process Group: DEFAULT, pseudo proc: 0x9b11ca008 O/S info: user: oracle, term: UNKNOWN, ospid: 29967 OSD pid info: Unix process pid: 29967, image: oracle@ebtadbsvr2 (MMON) |
从上面的 trace 可以看到之前一直被等待的 993cfec60 资源（Childobject queue header operation）正被 mmon 进程持有。
21:50:29 的时候 LCK0 在等待 mmon 释放资源，而此时 mmon 出现异常，因此在 21:51:06 mmon 进程被 LMHB 强制重启。然后在重启后，由于 mmon 的异常，导致 21:54:18 该资源仍无法被 lck0 进程正常持有，最终导致 21:54:20LMHB 进程强制重启了整个实例。
因此，最终的罪魁祸首是 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，如下：
SO: 0x9914dbce8, type: 4, owner: 0x9911283b0, flag:INIT/-/-/0x00 if: 0x3 c: 0x3 proc=0x9911283b0, name=session, file=ksu.hLINE:11467, pg=0 (session) sid: 1729 ser: 3 trans: (nil),creator: 0x9911283b0 flags: (0x51)USR/- flags_idl: (0x1) BSY/-/-/-/-/- flags2: (0x408)-/- DID: ,short-term DID: txn branch:(nil) oct: 0, prv: 0,sql: (nil), psql: (nil), user: 0/SYS ksuxds FALSE at location: 0 service name: SYS$BACKGROUND Current Wait Stack: Not inwait; last wait ended 1 min 39 sec ago There are 3 sessions blocked by this session. Dumping one waiter: inst: 2, sid: 1009, ser: 1 wait event: 'latch: object queue headeroperation' p1: 'address'=0x993cfec60 p2: 'number'=0xa2 p3: 'tries'=0x0 row_wait_obj#: 4294967295, block#: 0, row#:0, file# 0 min_blocked_time: 81 secs,waiter_cache_ver: 14285 Wait State: fixed_waits=0 flags=0x20 boundary=(nil)/-1 |
对于数据库进程，如果状态不是 dead，而是 busy，而且持有 latch 不释放，那么唯一的一种解释即进程被挂起，而 lck0 持有的 latch 是 objectqueue header operation。oracle mos 文档也有关于该 event 的描述如下：Scans of the object queue in thebuffer cache can hold the "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 强制失效子游标的方式来防止子游标过多的情况，操作如下：
如何加入云和恩墨大讲堂微信群
搜索盖国强（Eygle）微信号：eeygle，或者扫描下面二维码，备注：云和恩墨大讲堂，即可入群。每周与千人共享免费技术分享，与讲师在线讨论。
云和恩墨
数据驱动，成就未来。整合业界顶尖的技术与合作伙伴资源，围绕数据及相关领域，提供解决方案和专业服务。
IT基础架构
zData一体机 - 分布式存储解决方案
数据架构
Oracle DB2 MySQL NoSQL
专项服务：架构 / 安全 / 高可用 / 容灾 / 优化 / SQL 质量管控
运维服务：运维服务 | 代维服务
人才培养：个人认证 | 企业内训
软件产品：SQL审核 - Z3 | 监控 - Zone | 数据恢复 - ODU
应用架构
应用软件开发：数据建模 | SQL审核和优化 | 中间件服务
业务架构
电子渠道（网络销售）分析系统 | 数据治理
恩墨学院
恩墨学院是云和恩墨(北京)信息技术有限公司旗下的培训事业部，创业数年专注于数据库认证、技能培训，以专业的讲师塑造品牌，以专业的训练保证就业，目前已经发展成为国内数据库领域培训领导品牌。
扫一扫
715
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
