大家好，我是云和恩墨的李轶楠，不过网上的朋友更习惯叫我600，所以我也慢慢熟悉了这个称呼，其实这个称呼来自于ITPUB论坛上当时我注册的论坛ID“ORA-600”，因为这个ID跟Oracle的著名错误号一样，很容易给大家留下深刻印象，所以被我借用了过来，呵呵。这些年通过论坛上认识了很多朋友，也结识了现在与我一起奋战的恩墨小伙伴们。
闲话不多说，我们来看看我们今天要分享的主题吧，这些年我们积累了大量的客户群体，也意味着我们面对着各种复杂的环境与事件，后续我会把我们小伙伴们所遭遇到的各种或者经典、或者灵异、或者有趣的case，逐一做成案件分析来分享给大家，希望大家喜欢。今天就以去年我们所遇到的一次RAC节点宕机的故障作为开场吧。
1.案情描述
2015年6月的一个傍晚，大雨滂沱，正坐在家里发呆中，突然被一阵铃声惊醒。拿起电话，发现是客户来电，于是赶紧接听：
”我们的核心系统在晚上9点多突然有一个节点挂了，实例自动重启。虽然没有影响业务，但这种无缘无故的重启发生在核心系统上，直接威胁我们的业务运行，领导很重视，所以今天必须把原因找到，多晚都要给出结果，拜托了！“
2.案情分析
听到客户的描述，心里第一个反应是：还好，只是单节点重启，问题本身应该不严重，至少对业务影响并不大，看来这大雨天是不用淋雨去客户现场了。。。呵呵，小心思而已。
客户目前急需的是快速给出问题的原因，以便根据情况作出后续的规避措施，所以需要尽快拿到现场的一些数据来做分析，毕竟分析所需要的信息数据距离故障时间越近，精准度就越高，越有利分析。
经过进一步的沟通，得到了一些案发时的基本信息：
重启的是整个数据库架构的2节点，这个库是核心系统，晚上也有业务；
重启实例的情况其实以前也发生过，只不过发生的不多；（潜台词是也许这不是个案，以前的重启意味着可能这个问题一直存在）
当前数据库版本为11.2.0.1。（看到每个大版本的第一个小版本，总是觉得这种系统会BUG缠身。。。虽然夸大了点，但我们确实遇到了不少这种小版本的BUG）
当然，很明显只听客户描述是不够的。于是，我远程登录了客户的服务器，开始做进一步检查。
在开始分析之前，先跟大家及一下故障分析的常规思路，也便于初学者在遇到问题的时候知道从何处入手。
在遇到故障时，首先要辨识一下当前的场景主要是性能问题的还是真的故障；
如果是性能问题，那就需要收集当时的系统性能信息与数据库性能信息，awr、ash，或者系统的nmon、top之类都可以；
如果是故障，那就要检查数据库的告警日志与跟踪文件了，非常典型的就是，这里面往往给了我们进一步追踪痕迹的指引。除此之外，各个进程的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的alertlog部分内容：
FriJun2620:24:522015
Errorsinfile/u01/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_p001_13581.trc(incident=204565):
ORA-00600:内部错误代码,参数:[kksfbc-wrong-kkscsflgs],[39913467504],[33],[],[],[],[],[],[],[],[],[]
Incidentdetailsin:/u01/app/oracle/diag/rdbms/orcl/orcl2/incident/incdir_204565/orcl2_p001_13581_
FriJun2620:25:062015
Tracedumpingisperformingid=[cdmp_206]
FriJun2620:25:062015
Sweep[inc][204565]:completed
Sweep[inc2][204565]:completed
FriJun2620:25:182015
Tracedumpingisperformingid=[cdmp_207]
。。。。。
FriJun2621:21:082015
ArchivedLogentry164580addedforthread2sequence48360ID0xa822d65adest1:
FriJun2621:41:092015
Thread2advancedtologsequence48362(LGWRswitch)
Currentlog48362mem2seq1:+DATA/orcl/onlinelog/
FriJun2621:41:092015
ArchivedLogentry164584addedforthread2sequence48361ID0xa822d65adest1:
FriJun2621:50:262015
LCK0(ospid:29987)waitsforlatch'objectqueueheaderoperation'for77secs.
Errorsinfile/u01/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_lmhb_29939.trc(incident=204141):
ORA-29771:processMMON(OSID29967)blocksLCK0(OSID29987)formorethan70seconds
Incidentdetailsin:/u01/app/oracle/diag/rdbms/orcl/orcl2/incident/incdir_204141/orcl2_lmhb_29939_
MMON(ospid:29967)isblockingLCK0(ospid:29987)inawait
LMHB(ospid:29939)killsMMON(ospid:29967).
PleasecheckLMHBtracefileformoredetail.
FriJun2621:51:062015
RestartingdeadbackgroundprocessMMON
FriJun2621:51:062015
MMONstartedwithpid=213,OSid=16612
FriJun2621:51:092015
Sweep[inc][204141]:completed
Sweep[inc2][204141]:completed
FriJun2621:54:102015
LMS1(ospid:29929)waitsforlatch'objectqueueheaderoperation'for81secs.
LCK0(ospid:29987)/u01/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_lmhb_29939.trc(incident=204142):
ORA-29770:globalenqueueprocessLMS1(OSID29929)ishungformorethan70seconds
Incidentdetailsin:/u01/app/oracle/diag/rdbms/orcl/orcl2/incident/incdir_204142/orcl2_lmhb_29939_
FriJun2621:54:202015
Errorsinfile/u01/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_lmhb_29939.trc(incident=204143):
ORA-29770:globalenqueueprocessLCK0(OSID29987)ishungformorethan70seconds
Incidentdetailsin:/u01/app/oracle/diag/rdbms/orcl/orcl2/incident/incdir_204143/orcl2_lmhb_29939_
ERROR:Someprocess(s)isnotmakingprogress.
LMHB(ospid:29939)isterminatingtheinstance.
PleasecheckLMHBtracefileformoredetails.
PleasealsochecktheCPUload,I/Oloadandothersystempropertiesforanomalousbehavior
ERROR:Someprocess(s)isnotmakingprogress.
LMHB(ospid:29939):terminatingtheinstanceduetoerror29770
FriJun2621:54:212015
opiodrabortingprocessunknownospid(26414)asaresultofORA-1092
FriJun2621:54:212015
ORA-1092:opitskabortingprocess
FriJun2621:54:212015
Systemstatedumpismadeforlocalinstance
SystemStatedumpedtotracefile/u01/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_diag_29889.trc
InstanceterminatedbyLMHB,pid=29939
SatJun2712:52:232015
StartingORACLEinstance(normal)
LICENSE_MAX_SESSION=0
LICENSE_SESSIONS_WARNING=0
Pickedlatch-freeSCNscheme3
Autotuneofundoretentionisturnedon.
LICENSE_MAX_USERS=0
SYSauditingisdisabled
在告警日志中我们发现一个很明显的ORA-600错误，同时也发现一些其他的ORA报错，见上面标红部分。于是我们对这些错误分别进行了分析，发现：
1）ORA-600[kksfbc-wrong-kkscsflgs]()确实是一个bug，在MOS上有说明：
NBBugFixedDescription906728211.2.0.1.2,11.2.0.1.BP01,11.2.0.3,12.1.0.1ORA-600[kksfbc-wrong-kkscsflgs]canoccur906613010.2.0.5,11.1.0.7.2,11.2.0.2,12.1.0.1OERI[kksfbc-wrong-kkscsflgs]/spinwithmultiplechildren882832811.2.0.1.1,11.2.0.1.BP04,11.2.0.2,12.1.0.1OERI[kksfbc-wrong-kkscsflgs]866116811.2.0.1.1,11.2.0.1.BP01,11.2.0.2,12.1.0.1OERI[kksfbc-wrong-kkscsflgs]canoccur但MOS上并未说明该BUG会导致实例宕机，这个600错误看来应该与此次重启关系不大，好吧，作为一个问题记下来就是了。
2）在故障时间点，LMHB进程check发现mmon进程阻塞了LCK0进程，超过70s，因此尝试killMMON进程，该进程被kill之后将会自动重启。
可以看到在Jun2621:51:06时间点，MMON进程重启完成。
这里在插播一件事，正好就在前几天，我们的客户也遇到了MMON进程的相关问题，在这也顺便分享给大家：客户的MMON进程被Kill之后并未自动启动，导致AWR等性能信息无法自动收集，因此客户希望能够在不启动数据库的情况下启动MMON，再想了各种办法之后，最终找到了方法：
Restartthedatabaseinstance
或者
Settheinstanceto"restrictedsession"modeandthenbringitbacktonormalmodeusingfollowingcommandsasSYSDBA:altersystemenablerestrictedsession;altersystemdisablerestrictedsession;
大家也可以搜寻一下MOS上的文章，看到相关的信息：文档
接下来，在Jun2621:54:10，LMS1进程报错无法获得latch（objectqueueheaderoperation）超过85秒。
2、为了更清楚的理清线索，我们根据节点2的alertlog信息，整理出如下的时间线点：
Jun2620:24:52ORA-00600[kksfbc-wrong-kkscsflgs]
Jun2621:50:26LCK0(ospid:29987)waitsforlatch'objectqueueheaderoperation'for77secsMMON(OSID29967)blocksLCK0(OSID29987)formorethan70secondsMMON(ospid:29967)isblockingLCK0(ospid:29987)inawaitLMHB(ospid:29939)killsMMON(ospid:29967)
Jun2621:51:06MMONstartedwithpid=213,OSid=16612Jun2621:54:10LMS1(ospid:29929)waitsforlatch'objectqueueheaderoperation'for81secsLCK0(ospid:29987)hasnotcalledawaitfor85secs
ORA-29770:globalenqueueprocessLMS1(OSID29929)ishungformorethan70seconds
Jun2621:54:20ORA-29770:globalenqueueprocessLCK0(OSID29987)ishungformorethan70seconds
ERROR:Someprocess(s)(ospid:29939)isterminatingtheinstance
LMHB(ospid:29939):terminatingtheinstanceduetoerror29770
从最后的信息可以看出,在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_，而该trace文件产生的时间点是：Jun2621:54:10：
SO:0x9a1175160,type:2,owner:(nil),flag:INIT/-/-/0x00if:0x3c:0x3
proc=0x9a1175160,name=process,file=:11459,pg=0
(process)Oraclepid:14,ser:1,callscur/top:0x9b17e5330/0x9b17e0e60
flags:(0x6)SYSTEM
flags2:(0x100),flags3:(0x0)
intrerror:0,callerror:0,sesserror:0,txnerror0
intrqueue:empty
ksudlpFALSEatlocation:0
(postinfo)lastpostreceived:00116
lastpostreceived-location::1810ID:KJCSPostsndproxytoflushmsglastprocesstopostme:99112633016
lastpostsent:4121
lastpostsent-location::2160ID:kslgeslastprocesspostedbyme:9811032c8114
(latchinfo)wait_event=0bits=a
Locationfromwherecallwasmade::890ID:kcbo_unlink_q_bg:
waitingfor993cfec60Childobjectqueueheaderoperationlevel=5child=20
Locationfromwherelatchisheld::3535ID:kclbla:
Contextsavedfromcall:0
state=busy(exclusive)[value=0x200000000000000e,holderorapid=14]wlstate=free[value=0]
holding(efd=5)9b45cac50Childcachebufferschainslevel=1child=117
Locationfromwherelatchisheld::3966ID:kclbufs:
Contextsavedfromcall:0
state=busy(shared)[value=0x000001]wlstate=free[value=0]
waiters[orapid(secondssince:putonlist,posted,alivecheck)]:14(95,1435326858,4)21(94,1435326858,7)
waitercount=2
ProcessGroup:DEFAULT,pseudoproc:0x9b11ca008
O/Sinfo:user:oracle,term:UNKNOWN,ospid:29987
OSDpidinfo:Unixprocesspid:29987,image:oracle@ebtadbsvr2(LCK0)
最后一句很明显的告诉我们，29987原来就是LCK0进程。这意味着lms1进程所等待的资源正被LCK0进程所持有。而同时还有另外一个进程orapid=21也在等待该进程。通过分析我们分析发现：
orapid=21，是dbw2进程，即数据库写进程。
5、从数据库alertlog来看，在Jun2621:54:10有提示lck0进程已经超过85秒没有响应
LCK0(ospid:29987)hasnotcalledawaitfor85secs
根据时间点来计算，大概在Jun2621:52:45点左右开始，LCK0进程即没有响应了。
那么很明显，我们只要知道LCK0进程为什么会hung，就知道了此次故障的原因。
那么我们来看看LCK0的trace文件，看能不能看到一些线索。
6、LCK0进程的trace信息
***2015-06-2621:50:29.329Processdiagnosticdumpfororacle@ebtadbsvr2(LCK0),OSid=29987,
pid:36,proc_ser:2,sid:1729,sess_ser:3-------------------------------------------------------------------------------
loadavg:6.4726.9634.97Memory(Avail/Total)=10598.05M/64421.55M
Swap(Avail/Total)=20256.00M/20479.99M
FSUIDPIDPPIDCPRINIADDRSZWCHANSTIMETTYTIMECMD
0Soracle299871semtimApr05?01:25:21ora_lck0_orcl2
Shortstackdump:
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-2621:54:18.438Processdiagnosticdumpfororacle@ebtadbsvr2(LCK0),OSid=29987,
pid:36,proc_ser:2,sid:1729,sess_ser:3-------------------------------------------------------------------------------
loadavg:2.0413.3427.63Memory(Avail/Total)=9519.06M/64421.55M
Swap(Avail/Total)=20256.00M/20479.99M
FSUIDPIDPPIDCPRINIADDRSZWCHANSTIMETTYTIMECMD0Roracle299871?Apr05?01:26:55ora_lck0_orcl2
Shortstackdump:
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/-/-/0x00if:0x3c:0x3
proc=0x9d10f97c0,name=process,file=:11459,pg=0
(process)Oraclepid:31,ser:1,callscur/top:0x965657408/0x9b17e3f18
flags:(0x2)SYSTEM
flags2:(0x20),flags3:(0x0)
intrerror:0,callerror:0,sesserror:0,txnerror0
intrqueue:empty
ksudlpFALSEatlocation:0
(postinfo)lastpostreceived:0035
lastpostreceived-location::603ID:ksrpublishlastprocesstopostme:9911283b026
lastpostsent:0026
lastpostsent-location::282ID:ksasndlastprocesspostedbyme:9911283b026
(latchinfo)wait_event=0bits=26
holding(efd=7)993cfec60Childobjectqueueheaderoperationlevel=5child=233
Locationfromwherelatchisheld::3601ID:kcbzgws:
Contextsavedfromcall:0
state=busy[holderorapid=31]wlstate=free[value=0]
holding(efd=7)9c2a99938Childcachebufferschainslevel=1child:4294967295,block:0,file#0
min_blocked_time:81secs,waiter_cache_ver:14285
WaitState:
fixed_waits=0flags=0x20boundary=(nil)/-1
对于数据库进程，如果状态不是dead，而是busy，而且持有latch不释放，那么这意味着该进程已被挂起，lck0持有的latch是objectqueueheaderoperation。oraclemos文档也有关于该event的描述如下：Scansoftheobjectqueueinthebuffercachecanholdthe"objectqueueheaderoperation"。
基于上述的分析，我们最终判断，lck0进程出现问题的原因与cursor子游标过多有关。同时，这又与在11.2.0.1版本上的childcursor总数阀值限制过高有关（实际在版本10g中就引入了该CursorObsolescence游标废弃特性，10g的childcursor的总数阀值是1024，即子游标超过1024即被过期，但是这个阀值在11g的初期版本中被移除了。这就导致出现一个父游标下大量childcursor即highversioncount的发生；由此引发了一系列的版本11.2.0.3之前的cursorsharing性能问题。这意味着版本11.2.0.1和11.2.0.2的数据库，将可能出现大量的Cursor:MutexS和librarycachelock等待事件这种症状，进而诱发其他故障的发生。
因此，强烈建议11.2.0.3以下的版本应尽快将数据库版本升级到11.2.0.3以上（11.2.0.3中默认就有”_cursor_obsolete_threshold”了，而且默认值为100），或者通过_cursor_features_enabled和106001event来强制控制子游标过多的情况。
3.结案陈词
该案例的分析还是有些曲折，因为常见导致单节点故障最常见的情况主要是心跳、节点资源之类，而该案例的诱发原因相对有些诡异，先是出现了ora-600错误，然后又报了killmmon的信息，这都让案情分析有些扑朔迷离，当然，最终我们还是找出了问题的主要根源。
通过该起案件我们发现：
数据库版本的选择绝对是影响系统稳定性的关键要点；
不要以为性能问题只是影响用户体验，有些性能问题是会诱发系统一系列问题的；
问题的分析不要想当然，通过trace逐步递进，结合原理与经验，才能更为准确的确定问题；
子游标过多千万不能小视，最好能找出根源并解决它，如果确实不好解决，那么可通过设置隐含参数_cursor_features_enabled和106001event强制失效子游标的方式来防止子游标过多的情况，操作如下：
SQLaltersystemset"_cursor_features_enabled"=300scope=spfile;
SQLaltersystemsetevent='106001tracenamecontextforever,level1024'scope=spfile;
正常重启数据库即可。
QA
1、在什么情况下可以重用父游标和子游标呢？
父游标只要SQL代码共享就可以重用，子游标的要求的比较多，特别是当使用了绑定变量或者谓词字段的数据分布倾斜的时候，很容易出现多个子游标的情况，具体子游标不能共享的原因，可以查v，这个视图里的一堆字段表明了某个特定父游标的子游标不能共享的各种原因
2、请问一下，监测rac心跳能否用直连网线？一般你们怎么做？
rac的心跳从原理上是可以使用直连网线的，但无论是稳定性还是传输速率都不能完全满足心跳的要求，因此Oracle从9i开始，在白皮书里明确写了不允许使用直连线的方式，主要就是出于心跳稳定和传输速率考虑。其实如果心跳压力非常小的话，用直连肯定也可以，只是用rac的大部分是核心，一般不愿意去冒险。
3、能不能简单说下rac的高可用和我们平时做的双机热备有哪些区别呀。
rac的高可用是两节点的数据库实例同时可用，而传统的ha则只是在一个节点上可用实例，另一个节点的实例并没有启动，因此，简单来说，rac比ha至少在高可用能力上更强（两节点同时在用，一旦单节点故障，故障节点的会话可以无缝切换到另一可用节点，前端没有业务中断的感觉，当然，这个需要配置好才行），而ha一旦单节点故障，业务一定得中断，等待另一节点实例起来之后才能连接。同时，rac也能同时发挥两台机器的效能，而ha的一个节点完全是浪费着（有的用户为了避免这种浪费，就把两个库分别在ha的两个节点运行，让两节点的两个库互为热备）
4、请问除了子游标以外，还有哪些因素会导致，RAC宕机或者导致其不稳定。
rac不稳定的因素很多，最典型的就是心跳线不稳定或者心跳线出现数据风暴，此外，11g的DRM特性也很容易导致rac单节点宕机，一般我们都会建议禁用DRM特性。此外，11g还有很多新特性都会诱发节点宕机，比如我们以前还遇到过由于asm实例内存太小，而在rac的asm上部署的数据库太多导致asm实例挂掉，从而导致rac库宕掉的。原因很多了
5、能否简单介绍下在oracle优化中对游标的优化思路与RAC常用优化方向。
游标的优化思路，最简单也是最根本的就是在适当的场景下用绑定变量，在不该用的时候不要乱用绑定。比如，谓词倾斜的字段就极度不适合绑定。另外，统计信息的准确性，尤其是倾斜字段的统计信息准确性也直接影响着子游标的产生。还有一些参数也要注意，特别是cursor_sharing，宁愿设置成force，也尽量不要用similar，similar很容易遭遇bug，导致一堆子游标撑爆sharedpool。最后就是我们那个案例中的不同版本对子游标数的限制，不能放任子游标无穷增长。
rac的优化牵扯面比较多，我先零零星星写一些吧，太多了。比如sequence，在rac下一定要开启cache，而且不能太小，我们对于一些常用的sequence甚至建议开启cache到500以上，决不能使用order。
再比如如果发现GC的enq特别多，那么就要考虑做业务分割，把操作不同表的会话连接到不同的节点实例上，减少两节点对同一张表的征用。
6、请说一下，RAC宕机的处理思路，谢谢。
对于宕机，基本上都是从数据库的看起，一般告警日志里都会有最后宕掉时数据库做的事情，甚至有更为详细的trace文件信息，那么就需要根据这些信息结合rac各进程的关系来进行分析，这个的确不是一两句话能说的完的。总之，肯定是要看数据库告警日志和crs日志的，asm的日志有时候也要看。而导致宕机的原因同样五花八门，有些是系统原因，比如asm存储阵列出问题、光纤链路不稳定、swap耗尽等等，有些是数据库问题，比如心跳检测超时，为了恢复出问题的节点，自动宕掉那个节点重启，比如由于一些数据库的bug或者异常导致Oracle的某些关键进程被强制杀掉之类。。。可能性非常多了
