技术培训 | 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/的各个子目录），更详细的在这里就不再展开了。
• 另外，当遭遇这些问题的时候，如果有MOS账号的话，建议首先去MOS中查看是否有故障相关的BUG或者技术文章，这既是快速诊断问题、解决问题的途径，也是DBA快速成长的重要手段。关于MOS的使用，大家可以加公众号“oracle”，在其中可以看到5月5日发的一篇“Oracle初学者入门指南-什么是Metalink或MOS？”

好吧，回到我们的案例中：

1、下面是节点2的alert log部分内容：

Fri Jun 26 20:24:52 2015
 Errors in file /u01/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_p001_13581.trc  (incident=204565):
 ORA-00600: 内部错误代码, 参数: [kksfbc-wrong-kkscsflgs], [39913467504], [33], [], [], [], [], [], [], [], [], []
 Incident details in: /u01/app/oracle/diag/rdbms/orcl/orcl2/incident/incdir_204565/orcl2_p001_13581_i204565.trc
 Fri Jun 26 20:25:06 2015
 Trace dumping is performing id=[cdmp_20150626202506]
 Fri Jun 26 20:25:06 2015
 Sweep [inc][204565]: completed
 Sweep [inc2][204565]: completed
 Fri Jun 26 20:25:18 2015
 Trace dumping is performing id=[cdmp_20150626202517]
 。。。。。
 Fri Jun 26 21:21:08 2015
 Archived Log entry 164580 added for thread 2 sequence 48360 ID 0xa822d65a dest 1:
 Fri Jun 26 21:41:09 2015
 Thread 2 advanced to log sequence 48362 (LGWR switch)
   Current log# 2 seq# 48362 mem# 0: +DATA/orcl/onlinelog/redo21.log
   Current log# 2 seq# 48362 mem# 1: +DATA/orcl/onlinelog/redo22.log
 Fri Jun 26 21:41:09 2015
 Archived Log entry 164584 added for thread 2 sequence 48361 ID 0xa822d65a dest 1:
 Fri Jun 26 21:50:26 2015
 LCK0 (ospid: 29987) waits for latch 'object queue header operation' for 77 secs.
 Errors in file /u01/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_lmhb_29939.trc  (incident=204141):
 ORA-29771: process MMON (OSID 29967) blocks LCK0 (OSID 29987) for more than 70 seconds
 Incident details in: /u01/app/oracle/diag/rdbms/orcl/orcl2/incident/incdir_204141/orcl2_lmhb_29939_i204141.trc
 MMON (ospid: 29967) is blocking LCK0 (ospid: 29987) in a wait
 LMHB (ospid: 29939) kills MMON (ospid: 29967).
 Please check LMHB trace file for more detail.
 Fri Jun 26 21:51:06 2015
 Restarting dead background process MMON
 Fri Jun 26 21:51:06 2015
 MMON started with pid=213, OS id=16612
 Fri Jun 26 21:51:09 2015
 Sweep [inc][204141]: completed
 Sweep [inc2][204141]: completed
 Fri Jun 26 21:54:10 2015
 LMS1 (ospid: 29929) waits for latch 'object queue header operation' for 81 secs.
 LCK0 (ospid: 29987) has not called a wait for 85 secs.
 Errors in file /u01/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_lmhb_29939.trc  (incident=204142):
 ORA-29770: global enqueue process LMS1 (OSID 29929) is hung for more than 70 seconds
  Incident details in: /u01/app/oracle/diag/rdbms/orcl/orcl2/incident/incdir_204142/orcl2_lmhb_29939_i204142.trc
 Fri Jun 26 21:54:20 2015
 Errors in file /u01/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_lmhb_29939.trc  (incident=204143):
 ORA-29770: global enqueue process LCK0 (OSID 29987) is hung for more than 70 seconds
 Incident details in: /u01/app/oracle/diag/rdbms/orcl/orcl2/incident/incdir_204143/orcl2_lmhb_29939_i204143.trc
 ERROR: Some process(s) is not making progress.
 LMHB (ospid: 29939) is terminating the instance.
 Please check LMHB trace file for more details.
 Please also check the CPU load, I/O load and other system properties for anomalous behavior
 ERROR: Some process(s) is not making progress.
 LMHB (ospid: 29939): terminating the instance due to error 29770
 Fri Jun 26 21:54:21 2015
 opiodr aborting process unknown ospid (26414) as a result of ORA-1092
 Fri Jun 26 21:54:21 2015
 ORA-1092 : opitsk aborting process
 Fri Jun 26 21:54:21 2015
 System state dump is made for local instance
 System State dumped to trace file /u01/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_diag_29889.trc
 Instance terminated by LMHB, pid = 29939
 Sat Jun 27 12:52:23 2015
 Starting ORACLE instance (normal)
 LICENSE_MAX_SESSION = 0
 LICENSE_SESSIONS_WARNING = 0
 Interface type 1 eth1 172.16.0.0 configured from GPnP Profile for use as a cluster interconnect
 Interface type 1 eth0 192.168.0.128 configured from GPnP Profile for use as a public interface
 Picked latch-free SCN scheme 3
 Autotune of undo retention is turned on.
 LICENSE_MAX_USERS = 0
 SYS auditing is disabled

在告警日志中我们发现一个很明显的ORA-600错误，同时也发现一些其他的ORA报错，见上面标红部分。于是我们对这些错误分别进行了分析，发现：

1&