九乡新闻网荣威360怎么样毛病多不:[白鳝10] 第4章 经常宕机的RAC系统2
来源：百度文库 编辑：九乡新闻网 时间：2024/04/30 10:41:06
第4章 经常宕机的RAC系统
4.1 3月2日 上海的紧急故障
今天晚上上海的雷总突然打电话过来，说有件事需要我们帮下忙。我问他是什么事，他说是一个客户的系统宕机的问题，最好能够尽快过来一下。我说没问题，明天一早就派工程师过去。老雷一听就急了，老白不是我不信任你的弟兄，这件事很棘手，你必须亲自跑一趟。我半开玩笑的说，你的客户都是券商，能有多大的事情，还非我不行，我可以给你从南京派人，不仅可以为你省点路费而且今天晚上就可以赶过去。
和老雷聊了半天，才搞明白是他们的客户的一套2个节点的RAC系统，其中一个节点总是莫名其妙的宕机。由于这是一个券商的生产系统，因此宕机可能引起很严重的问题，2月份的时候，他们在metalink上开了个tar，Oracle GCS的工程师远程分析了半个月了，到目前为止还是没有任何进展。今天下午股市收市前突然那个节点又宕了，造成了7分钟的业务中断，给券商造成了很大的损失。从他们现场工程师的判断，这个问题应该不是一般人能够解决的，因此他坚持我亲自过去帮助处理一下。老雷说这个问题已经在上海找了很多Oracle的高手，不过都是摸不着头脑，客户对此也提心吊胆的，生怕今天的现象重演，因此他必须找到问题，并且尽快解决问题，如果是他们的应用程序的问题，如果不能很快解决掉，那么他们也可能面临客户的索赔。
听老雷这么一说，我也感觉到了问题的严重性，这种宕机的问题，系统、应用、数据库掺杂在一起，确实很难分析。说实在的，我也没有解决问题的绝对把握。看样子我必须亲自跑一趟上海了。
刚订好机票，老雷手下的小陈就已经把日志上传到我的服务器上了。日志文件很大，有200多M，是2月22号和26号宕机时的日志。小陈做事很细心，把两个节点的bdump/udump目录，以及CRS_HOME下的log全部打包，并用RDA采集了大量的数据。这些数据之前也通过METALINK上传给了ORACLE GCS。通过小陈，我也了解到了这是一套10.2.0.3的RAC系统，安装在两台微机服务器上，每台服务器配置是8个CPU，16G内存，安装操作系统的是64位的redhat linux as4 update4 Linux yhshora1 2.6.9-42.ELlargesmp。CRS已经安装了BUNDLE PATCH 1。
这套系统是2月10号安装的，安装后不久就出现过一次宕机，那时候系统还没有正式上线，上线后，2月22号就出现过一次宕机的情况，从CRS的日志中看不到什么异常，不过在ocssd的日志里可以看到一些信息：
ocssd.log node1
[ CSSD]2008-02-10 05:20:13.521 [1231087968] >TRACE: clssgmHandleDBDone(): src/dest (2/65535) size(72) i
ncarn 2
[ CSSD]CLSS-3000: reconfiguration successful, incarnation 2 with 2 nodes
[ CSSD]CLSS-3001: local node number 1, master node number 2
[ CSSD]2008-02-10 05:20:13.521 [1273047392] >TRACE: clssgmReconfigThread: completed for
reconfig(2), with status(1)
[ CSSD]2008-02-10 05:20:13.658 [1231087968] >TRACE: clssgmCommonAddMember: clsomon joined (1/0x1000000/#CSS_CLSSOMON)
[ CSSD]2008-02-22 02:46:16.958 [1231087968] >TRACE: clscsendx: (0x2a97a15210) Connection not active
[ CSSD]2008-02-22 02:46:16.958 [1231087968] >TRACE: clssgmSendClient: Send failed rc 6, con (0x2a97a15210), client (0x2a97a15510), proc ((nil))
[ CSSD]2008-02-22 02:46:17.368 [1126189408] >WARNING: clssnmDPT: timeout waiting on lock (71290 ms/61000 ms)
[ CSSD]2008-02-22 02:46:17.368 [1115699552] >WARNING: clssnmDPT: timeout waiting on lock (71020 ms/61000 ms)
[ CSSD]2008-02-22 02:46:17.368 [1178638688] >WARNING: clssnmDiskPMT: sltscvtimewait timeout (70760)
ocssd.log node2
[ CSSD]2008-02-10 05:20:12.554 [1273047392] >TRACE: clssgmMasterSendDBDone: group/lock status synchronization complete
[ CSSD]CLSS-3000: reconfiguration successful, incarnation 2 with 2 nodes
[ CSSD]CLSS-3001: local node number 2, master node number 2
[ CSSD]2008-02-10 05:20:12.555 [1273047392] >TRACE: clssgmReconfigThread: completed for reconfig(2),with status(1)
[ CSSD]2008-02-22 02:45:30.683 [1241577824] >WARNING: clssnmPollingThread: node yhshsec1 (1) at 50 1.482197e-323artbeat fatal, eviction in 29
.950 seconds
...
[ CSSD]2008-02-22 02:46:00.631 [1241577824] >TRACE: clssnmPollingThread: Eviction started for node yhshsec1 (1), flags 0x040d, state 3, wt
4c 0
上面的粗体字部分是典型的节点驱逐的日志信息，从上述信息可以看出节点yhshsec1是被yhshsec2驱逐才导致宕机的。那么是什么原因造成了节点1被节点2驱逐呢？从上面的粗体字部分可以看到，首先是clssgmSendClient出现了故障，从return code 6来看是节点通讯出现了故障，可能和网络中断或者其他故障有关，不过从时间序列上看，节点2驱逐节点1是02：46：00.631，而节点1报网络故障的时间是02:46:16.958，因此也有可能这个网络错误是由于节点2驱逐节点1而造成的，因为一旦驱逐发起，节点2会主动断开和被驱逐节点的cssd的通讯。因此仅仅通过上面的信息，还无法对错误原因进行定位。在处理rac系统当机故障的时候，由于rac涉及的情况比较复杂，我会将能够收集到的各种事件列一个时间顺序序列，我通过crsd,cssd,alert log等日志文件，整理了一下22号宕机前的时间序列：
- 2008-02-22 02：45：30： 实例2的CSSD进程发现实例1心跳超时，准备发起驱逐
- 2008-02-22 02：46：00 ：实例2发起对实例1的驱逐
- 2008-02-22 02：46：14： 实例二出现CORE DUMP id = [cdmp_20080222024619]
- 2008-02-22 02：46：16 ：实例1发现clscsendx: (0x2a97a15210) Connection not active
- 2008-02-22 02：48：16 ： 实例1报错：Error: KGXGN aborts the instance (6) CKPT: terminating instance due to error 481 实例1宕机
- 2008-02-22 02：46：32 ：实例2发现clscsendx: (0x2a9830bf60) Physical connection (0x2a9830b890) not active
- 2008-02-22 02：47：15 实例2的RAC进行重组
可以看出，实例1宕机是由于被实例2驱逐引起的。而实例2是发现实例1的心跳超时，才进行超时的。被驱逐之前，实例1工作正常。从22号的日志里根本看不出实例1出现故障的信息，也就无法定位实例1的心跳为什么会超时。我又赶紧打开2月26日宕机的日志进行分析，发现时间序列是：
- 2008-02-26 15:02:25 实例2：发现实例1心跳超时，准备半分钟后发起驱逐：WARNING: clssnmPollingThread: node yhshora1 (1) at 50 1.482197e-323artbeat fatal, eviction in 29.150 seconds
- 2008-02-26 15:04:51.715 实例1： 0CAAMonitorHandler :: 0:Could not join /oracle/crs/bin/racgwrap(check)
- 2008-02-26 15:04:52.209实例1： 0CAAMonitorHandler :: 0:Action Script /oracle/crs/bin/racgwrap(check) timed out for ora.yhshora1.vip! (timeout=60)
- 2008-02-26 15:06:00 实例1 ：报 WARNING: inbound connection timed out (ORA-3136)
- 2008-02-26 15:06:59 实例1：报 Process q002 died, see its trace file
- 2008-02-26 15:07:45 实例2：发起驱逐 TRACE: clssnmPollingThread: Eviction started for node yhshora1 (1), flags 0x040f, state 3, wt4c 0
- 2008-02-26 15:08:13 实例2：驱逐完成
- 2008-02-26 15:08:13 实例2：的CSD发现 prom_rpc: CLSC recv failure..ret code 7
- 2008-02-26 15:08:16 实例2 ：alert log报reconfiguration
和22号宕机的情况很类似，都是由于实例2发现实例1的心跳超时，开始驱逐。这两次宕机的情况十分类似，唯一不同的是，那么在驱逐没有开始前，实例1已经发现VIP超时。不过从26号宕机的日志里，仍然无法定位实例1宕机的原因。看一下今天的宕机日志有助于分析问题，不过由于日志文件很大，今天宕机的日志还没有来得及上传，只能明天我到了现场再看了。从宕机的时间来看，2月22日是半夜2点46分，系统没有任何业务在跑的时候，2月26日那次宕机是在15点08分，是股市刚刚收市不久，当时的系统业务量应该也不大，在15点之前可能会出现一个业务量的小高潮，不过经过8分钟，应该早就平息了。只有今天的宕机是发生在下午的2：47分，正是尾盘高峰的时候。
在Metalink上我查找了一些资料，发现CSSD出现故障，导致实例重启的一般情况有以下几种：
- 网络问题，当出现私有网络故障的时候可能导致CSSD通讯故障，比如出现交换机闪断、网卡故障或者网线被拔出等现象的时候会出现CSSD通讯故障
- VOTE DISK读写问题，当VOTE DISK读写故障的时候，也会导致CSSD通讯出现故障，对于VOTE DISK读写问题，会有类似的日志：clssnmDiskPingMonitorThread: voting device access hanging (xxxxxx miliseconds)
- 系统资源紧张，比如CPU资源不足，在一个突发的业务高峰到来的时候，CSSD无法获得执行的CPU时间，这样无法和其他节点正常通讯，其他节点会认为该节点不可用，从而导致驱逐
- CRS安装目录中某些重要文件被误删，导致CSSD堆栈出现故障，在这种高安全性要求的环境下，这种问题发生的可能性基本为0
- CRS配置错误，比如选错了private通讯网卡，从日志上看， clssnmClusterListener: Listening on (ADDRESS= (PROTOCOL=tcp)(HOST =yhshsec1-pri) (PORT=49895)) ，通过HOSTS文件，我们可以确认yhshsec1-pri是正确的
- VOTE DISK的IO出现问题，现场工程师已经检查过操作系统日志以及检查外接盘阵的日志，均未发现存储出现故障的迹象，这个问题也基本可以排除
- init.cssd fatal进程或者ocssd进程被kill -9干掉，这个可能性也较小，因为券商的安全管理十分严格，而且这个系统多次出现类似故障，不大可能是有人为的误操作
- Oracle bug导致，10G的CRS存在很多BUG，其中不少BUG会导致CRS异常，本系统的CRS已经升级到了10.2.0.3，而且已经安装了CRS的BUNDLE PATCH 1，这个版本的CRS基本上算是比较稳定的，CRS故障的BUG相对较少
首先我怀疑是不是由于某个BUG引起的故障。所以从METALINK上下载了几十个相关BUG的资料，晚上是没有心思看了，明天上午在飞机上看看吧。小陈已经在METALINK上开了个服务请求（SR，习惯上很多老DBA还是喜欢称为“开TAR”）,我登录到METALINK去看了一下，是一个叫Philippe的印度人在处理这个案子， 看了一下他的留言，也没有什么特别有价值的地方：
We just can delay the reboot, but the clusterware need to reboot the blocked system to avoid full database hangs.
The remaining instance and system is blocked during that time (during the reconfiguration or because the failing node is holding some locks/buffer needed by the other node). So, it is always possible to delay the reboot a bit, but at the expense of a longer hanging situation for the remaining node.
note:284752.1 explains how to change the css timeout value. It is set today to 60 (seconds), but can be set to 300 to try to avoid that an eviction get declared rapidly. It then give 5min to the blocked system to recope from the activity blocking everything (instead of 1min).
Please install the patch:5679560 (see note:5679560.8). It will update the init* files with scripts that are more robust agains sporadic cpu shortages, i.e. they don't trigger a potentially unnecessary reboot due
to bug:5679560. They can also log something more in case of problems in the /var/log/messages Please keep collecting the oswatcher data afterwards for a while (in case of).
他建议打一个补丁，并且通过修改css timeout来减少这种驱逐现象。加大TIMEOUT，可以减少误驱逐的可能性，但是真正出现实例故障的时候会加大FAILOVER的时间，还会引起一些其他方面的问题，在这种敏感的业务系统里，还是要十分谨慎的，看样子他给出的也不是一个很好的建议。现在已经是下半夜了，明天6点多还要起来赶飞机，早点休息吧。
4.2. 3月3日 上海第一天
昨天晚上我花了大概2个小时分析小陈发过来的日志文件，看完之后就十分疲惫了，为了在到达现场前多做一些准备，晚上我还是从网上下载了二十几个相关的BUG文档。深圳飞上海将近2个小时，除去早餐时间，还可以有个把小时来阅读这些文档。
吃过一顿十分简陋的机上早餐后，我打开电脑，又认真的分析起日志来。昨天晚上我在METALINK上下载了二十几个BUG报告，因此这回查看日志的时候，就更有针对性了。通过把日志和BUG报告中的场景进行比对，可以更有有效的分析日志。在查看日志的时候，我又有了一个十分惊人的发现：
Mon Mar 3 10:09:54 2008
Thread 1 advanced to log sequence 261
Current log# 1 seq# 261 mem# 0: /oradata/secrac/redo1_1
Mon Mar 3 13:46:17 2008
Thread 1 advanced to log sequence 262
Current log# 2 seq# 262 mem# 0: /oradata/secrac/redo1_2
Sun Mar 2 14:06:19 2008
Starting ORACLE instance (normal)
LICENSE_MAX_SESSION = 0
LICENSE_SESSIONS_WARNING = 0
Interface type 1 bond1 10.10.10.0 configured from OCR for use as a cluster interconnect
Interface type 1 bond0 192.168.20.0 configured from OCR for use as a public interface
Picked latch-free SCN scheme 3
Autotune of undo retention is turned on.
LICENSE_MAX_USERS = 0
在宕机前后的10多分钟时间里，日志完全是空白，这种现象十分正常，由于CSSD故障后CRS重启了这个节点，因此部分在缓冲池里的日志数据还没来得及写入文件，系统就重启了。值得注意的是，系统重启后这个节点的时间居然从22号变为21号，时间居然发生了倒流！这会不会是引起宕机的根本原因呢？由于两个节点时间不同步导致宕机的相关案例比较多，这个时间上的变化是不是就是引起宕机的主要原因呢？这一点需要下了飞机就立即确认一下，因为这有可能成为整个事情的突破点。
虽然感觉抓到了一个突破点，有些兴奋，不过我还是认认真真的阅读了十多个BUG报告。其中一个报告引起了我的注意，BUG 5632897是一个10.2.0.2上出现的案例，在AIX 5.3 ML4上出现。最终被确定为是由于操作系统虚拟内存不足导致，在业务高峰的时候，由于某个节点内存不足，导致系统性能下降，CSSD进程无法获得时间片运行，导致另外一个节点认为这个节点宕了，所以被驱逐了。从日志上看，确实这个案例有很多类似的地方，包括VIP超时。由于资源问题导致的RAC宕机我也经常会遇到，在我的一个税务系统的客户那里，以前就碰到过9.2.0.7的数据库由于系统产生大规模换页导致这个节点被另外一个节点驱逐。不过从另外一个角度看，这两个案例有太多的不同，第一是操作系统不同，AIX和LINUX；第二是版本不同，一个是10.2.0.2，而我们现在的系统是10.2.0.3 BUNDLE 1；第三是一个在业务高峰期间宕机，而客户那边宕机的时间没规律，有事甚至在没有什么业务的半夜；最后一点是这个BUG两个节点都有可能因为业务繁忙宕机，而客户这边宕机现象主要集中在第一个节点上。
虽然坐了最早的航班，不过到客户的办公室已经是中午了，客户的交易系统是和外网隔离的系统，所以我到了那里只是很陈工交流了几句，就下去吃午饭了。午饭后，我拿到了3月2号宕机的所有日志。并认真的分析起来，客户的系统每次都是1号节点会宕机，3月2也不例外，从日志上看，宕机的节点的CRSD和CSSD的日志都没有什么特殊的信息。甚至message日志里也没有什么特别的地方，在宕机前个把小时到系统重启这段时间的日志生生的缺失了。小陈对这个也感到很疑惑，我告诉小陈，因为节点被驱逐，所以服务器发生了重启，而重启的时候message日志的部分内容可能还在文件缓冲里，没来得及写入文件，所以就会出现类似的现象。crsd，ocssd日志也存在类似的问题。
看完日志，我把在飞机上看到的时间回退了一天的问题和小陈交流了一下，小陈说他已经发现了这个问题，最开始的时候，他们也以为这是宕机的原因。后来经过分析才搞明白是个误会。他们以前安装操作系统的时候不小心把日期设置错了，后来在Linux上通过date修改了时间，本来以为时间是同步的了，没想到date修改的日期只是修改了LINUX的时间，而并没有写入cmos。一旦服务器重启，又回恢复cmos的时间，上回宕机后他们修改了CMOS时间，就没有再次出现时间回退的问题了。
看样子我的第一怀疑对象完全落空了，和时间相关的几个BUG看样子都不需要考虑了，我在飞机上也查阅了几个和两个节点时间差相关的BUG，不过这些BUG基本上在10.2.0.3 BUNDLE PATCH 1之后解决了。由于2月份开tar的时候GCS的技术人员要求他们安装osw来监控操作系统的情况，这让我如获至宝，在分析rac问题的时候，有操作系统的实时监控数据是十分有帮助的，他们的监控数据是每隔10秒钟采集3次数据，每次采集数据间隔2秒。监控密度相当高，很可能我能够从中获得一些有用的东西。
从3月2日宕机前的OSW来看，在宕机前操作系统确实有异常的现象，从vmstat的信息上看，在宕机前的一刻，出现了瞬间CPU高峰：
procs -----------memory---------- ---swap-- -----io---- --system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
24 0 204360 14768 7592 6056904 0 0 55 27 2 2 1 1 98 0
4 4 204360 16464 5196 6056248 0 0 9411 414 4064 5694 8 70 16 5
0 8 204284 15608 2720 6056704 188 0 20581 1986 6160 11735 8 30 49 13
SYS的CPU消耗突然上升，r队列突然冲到24，2秒钟后恢复到4。这个时候发生了什么呢？我立即查看了相同时间段的io监控数据：
avg-cpu: %user %nice %sys %iowait %idle
7.66 0.00 52.12 8.48 31.74
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util
cciss/c0d0 45.00 162.00 560.67 41.00 23032.00 1613.33 11516.00 806.67 40.96 25.04 41.78 1.12 67.13
sda 0.00 0.00 3.67 13.67 1374.67 140.33 687.33 70.17 87.40 0.02 1.15 0.96 1.67
sdb 0.00 0.00 96.00 10.67 3015.33 214.33 1507.67 107.17 30.28 0.05 0.48 0.48 5.17
sdc 0.00 0.00 2.00 6.67 12.33 246.00 6.17 123.00 29.81 0.01 0.69 0.69 0.60
sdd 0.00 85.00 6.00 47.67 50.00 1105.00 25.00 552.50 21.52 0.09 1.63 0.74 3.97
sde 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
在相同的时间点上，Sda,sdb的访问量突然提高。Sdb是swap所在的分区，这立即让我感觉到，是不是在出现问题的时间点上，系统产生了大量的换页。SYS CPU突然变大，SWAP所在磁盘访问量突然增大，这是典型的换页现象。于是我立即查看这个时间点的MEMINFO的信息：
MemTotal: 16412244 kB
MemFree: 14616 kB ----空闲内存不足15M
Buffers: 7400 kB
Cached: 6054032 kB
SwapCached: 5696 kB
Active: 9638480 kB
Inactive: 58608 kB
HighTotal: 0 kB
HighFree: 0 kB
LowTotal: 16412244 kB
LowFree: 14616 kB
SwapTotal: 12289716 kB
SwapFree: 12085356 kB
Dirty: 12 kB
Writeback: 0 kB
Mapped: 9623404 kB
Slab: 400756 kB
CommitLimit: 20495836 kB
Committed_AS: 19278624 kB
PageTables: 2457724 kB
VmallocTotal: 536870911 kB
VmallocUsed: 268872 kB
VmallocChunk: 536601783 kB
HugePages_Total: 0
HugePages_Free: 0
Hugepagesize: 2048 kB
在怀疑有换页的时间点上，空闲的物理内存只有不足15M。这种情况下，确实可能产生大量的换页。于是我又有了一个推断，是不是由于换页而产生了宕机呢？从逻辑上来说，如果系统产生大量的换页，导致CPU被大量占用，这是一个4CPU，16G的LINUX环境，而等待运行队列曾一度高达24，这个期间，由于换页操作的优先级比较高，很可能导致cssd进程无法得到运行所需要的时间片，这样1号实例的cssd就无法与2号实例的cssd通讯，这个几秒钟的暂短的停顿，可能导致cssd通讯不正常，2号实例认为1号实例的节点出现了故障，从而导致2号节点做出了错误的驱逐命令，将1号节点从CLUSTER中驱逐出去，从而导致1号节点重启。这种情况在9i rac中我是碰到过的，有一个客户，由于ftp传输一个40多G的文件，导致物理内存耗尽，发生了大量换页，从而导致该实例被rac驱逐。从当时的OSW监控数据来看，产生大量换页的条件是存在的，因为在出问题前的时间点上，MEMINFO的监控数据表明，空闲的物理内存是相当有限的，这个时候如果有一个消耗内存较大的操作发生，那么就可能产生大量的换页操作，从而触发前面分析的那种导致节点被驱逐的条件。
我和小陈正在分析，上海的IT负责人谢总接了北京总部的顾总和负责系统维护的柳经理回到了公司。大家寒暄之后，谢总问我有什么发现，我把我到现场后做的工作简单的汇报了一下，然后把我刚才的推测说了出来。柳经理听了我的分析感觉有点道理，问我，你有什么资料可以证明这个推断的正确性呢？
我说资料很难找到，我以前碰到过一个案例，在AIX平台上，9i的rac，也出现过类似的问题。不过我也有一个简单的方法来验证这个推断，我们可以搭个环境做一下测试，做一些压力测试，让空闲的物理内存达到14M左右的低水平，这个时侯我们准备几个大型的对几张达标进行表连接，使用HASH或者SORT MERGE都可以，总之要消耗大量的排序空间那种，突然同时启动，这样如果能够模拟出节点被驱逐，那么就说明这个推测可能就是实际发生的情况。
顾总说，这个方法倒是可以，不过测试环境怎么搞，要和生产环境一样才好啊。
谢总想了想说，没关系，我们就在生产环境下搞。等3点钟闭市了，我们把数据库备份一下，然后这个环境就可以作为测试环境了，只要晚上12点统计程序启动前恢复回来就可以。
大家讨论了一下，证券公司的交易系统每天都把数据转储到历史数据库中，交易库里面实际上只有当天的交易数据，整个数据库只有几十个G,导入导出都很方便，这个方案可行。看看眼看就要到3点钟了，于是大家约好4点半正式开始测试。
讨论完毕后，大家就各自准备去了。我和小陈商量了一下，可以用他们的压力测试工具产生一定的系统压力，然后我们创建几张百来万条记录的大表，强制用hash做表连接，写一个SQL，当系统负载加载到一定程度，物理内存只剩下10多M的时候，同时在2、3台终端上跑这个SQL，就可以模拟出突发一个内存需求高峰的现象了。
现在是下午的3点30分了，小陈他们在做闭市后的例行数据导出工作。到4点半这段时间里，我没有具体的工作，就想找个地方上网查查资料。由于证券公司对网络权限管理很严格，所以我的电脑是无法直接连到客户的网络上的。小陈想帮我申请一个权限，打了一通电话，发现很复杂，没办法我只能使用小陈的电脑了。
这次我在网上搜索的文档主要是关于换页引起RAC节点被驱逐的。输入的关键字是“LINUX CRS REBOOT SWAP”，搜索到的结果有30多个，暂时没法一个一个的仔细阅读，所以我先把搜索的结果都保存了起来，准备晚上找时间再看。小陈那边的闭市后操作已经完成，时间也已经是下午的4点10分了。确认各项处理已经完毕，我们决定提前进行测试。小陈他们配置压力测试环境还需要半个小时左右的时间，我在中央监控机房开了三个终端，分别连到服务器上。趁着小陈他们还在准备环境，我仔细阅读了最近几次宕机前后的OSW日志。由于节点驱逐会直接导致linux服务器reboot，因此我查看OSW日志的时候，发现前几次宕机前的OSW日志大部分是空白，只有2月23号那次的OSW日志里有当时meminfo的日志，从meminfo的日志看，宕机前1号节点的物理内存空闲空间不到20M，而2号节点的空闲内存还有将近2g，这个现象和3月2号那次宕机的情况类似。
小陈那边已经停了交易应用，并且把把压力测试工具配置好了。刘工帮着小陈处理完测试环境，也坐到了我的身旁。我在一个监控窗口上运行了vmstat 1 ，每一秒钟采集一次系统的状态信息。在另外一个窗口不停的用free命令查看虚拟内存的变化。从vmstat上看，虽然压力加上去了，不过cpu的使用率还是保持在10%左右，空闲内存页面的数量从开始的80万（LINUX的物理页大小为1K，80万页相当于800M）不断的下降，目前已经不足600M了。通过free命令可以看到，buffer /cache的内存在不断的增大，这些现象和我以前的预计是完全相同的。只要空闲的物理内存下降到10多M，我们就可以在那几个预先准备好的终端上启动测试程序，尽快消耗掉所有的物理内存，造成物理换页的现象。我一边看着vmstat的结果，一边不停的做着ash报告，同时每隔10分钟做一个awr的采样点。
我打开一份刚刚生成的ash报告，和刘工一起阅读起来，从ash报告上看，目前的所有事务都是一些十分小的小事务，平均事务响应时间不足10毫秒。目前的压力测试程序，模拟的就是白天交易时的系统负载情况，只是压力测试程序释放的交易密度比正常交易高出1、2倍。我和刘工正在嘀嘀咕咕的讨论这份ASH报告，老雷突然从后面拍了拍我的肩膀，小白，有什么问题吗？
我说现在正在加压，要加到一定程度才能做测试。我和刘工正在分析现在的应用，从目前的现象上来看，应用造成问题的可能性很小，因为应用程序都是一些开销很小的小型事务。
老雷听到应用没有问题的说法，马上露出了灿烂的微笑，就是嘛，我们公司的技术在业界绝对是头把交椅，不可能是我们的应用引起的。
已经是5点40分了，目前1号节点上的物理内存还有30多M空闲，不过从物理内存下降的速度来看明显比刚才慢了不少。从目前的情况估算，如果物理内存下降到10来M起码还要2、30分钟，又看到顾总也忧心忡忡的和谢总坐在最旁边的监控台边上有一搭没一搭的聊着什么。估计领导也有点急了，于是我建议是不是再加点压，尽快早一点把物理内存降到20M以内。刘工建议还是按照交易的特点来测试，尽可能模拟现实情况，我想想也对，尽可能模拟现实情况，说服力更大一些。
物理内存终于降低到15M左右，这个时候已经是6点20多了。我和刘工商量了一下，就开始了我们预先设计好的测试程序。刘工开了2个PL/SQL DEVELOPER的窗口，分别跑了两个我们预先准备号的大查询，我也通过一个SQL*PLUS窗口运行了一个查询。几秒钟后，我发现跑着vmstat 1的窗口出现了停顿，几秒钟没有任何反应。通过另外一个窗口进去敲命令也没有任何反应。第一个感觉就是是不是系统宕了，大家都兴奋了起来。
经过几秒钟的兴奋后，突然终端上又开始显示出了一行一行的数字。系统并没有宕！刚才起码有5、6秒钟，系统没有任何反应，从现象上看应该是产生了大量的换页。我立即查看了Osw的日志，发现vmstat,iostat和meminfo日志的情况都和3月2号宕机的情况类似，不过sys cpu的使用率只有40%左右，没有出现r队列达到20多的现象。但是为什么今天系统没有宕呢？我立即查看了crsd和cssd日志，发现在刚才系统出现暂短停顿的时候，实例1出现了vip超时的告警，这和2月26号的情况很类似，不过vip超时报警之后，系统又回复了正常，并没有出现实例1被驱逐的现象。
这次实验虽然模拟出了我推断的由于换页出现了系统短时间hang住的现象，但是并没有模拟出宕机的现象，实验失败了。我和刘工总结了实验的情况，余光中突然发现顾总和谢总也站在旁边认真的听着，于是我就向顾总说，实验也不是一点成果也没有，起码我们模拟出了两个很可能导致宕机的现象，一个是由于突然发起一些大内存消耗的操作，触发了大规模的换页，从而产生了短暂的系统挂起。第二个是由于换页，系统短暂挂起，导致了vip超时错误的出现。系统没有出现宕机，可能是由于我们发起大内存消耗的查询的突然性还不够，导致没有触发宕机的条件。因此我建议再进行一次测试，这次测试使用一个开销更大的SQL。我看了看时间，现在已经是7点30了，大家都还没有吃饭，我建议顾总他们先去吃饭，我和刘工小陈做完实验再过去，否则大家都等在这边也不好。顾总坚持要和我们一起做完实验再吃。她说为了这个宕机的问题，她已经好几天没胃口了，如果我们能够解决这个问题，那么她今天的胃口一定会很好。
为了让实验更有代表性，所以在实验开始前我们和第一次实验一样重启了服务器。压力测试程序上虽然又多加载了20%的负载，让物理内存下降还是花费了差不多一个小时。这次的测试结果同样让人失望，虽然在测试的最后也出现了几秒钟的操作系统hang住的情况，不过我们一直期待的宕机仍然没有出现，甚至连vip超时都没有再出现。虽然对这种测试能够完全模拟出宕机现象，我的期望原本并不高，不过这次实验还是让我有点沮丧。刘工倒是觉得这次测试收获还是挺大的，起码验证了VM的这种机制会导致突发性的换页，使系统出现短时间的挂起。
实验再进行下去就没有什么意义了，于是我们准备先去吃饭。晚饭是老雷请客，公司旁边有家杭州菜馆还不错，于是大家就步行过去吃饭。在路上，我一直在考虑今天测试的要点，是不是我忽略了什么细节，才导致实验没有成功，还是因为我的推测完全是错误的，宕机的原因和换页没有任何关系呢？正想着，我突然一抬头，发现顾总正在我身边。
“小白，在考虑什么问题呢？”，顾总微笑着问我。我说在考虑今天实验没有成功的原因，可能我们还是无法模拟出那个突发事件，并且并不是每次换页都会导致节点驱逐。
“那么，你还是认为换页导致了这个问题吗？”顾总十分关心这个问题。
我考虑了一下回答说，从目前我分析到的所有BUG资料来看，没有一个能和目前的现象完全吻合，目前crs的版本已经是10.2.0.3 patch 1了，很多导致宕机的BUG应经在patch 1里修复了。而换页是目前最有可能导致节点驱逐的原因。
顾总和我聊一会实验的事情，突然说：“小白，你有没有考虑过到甲方去工作呢？我们的IT发展很迅速，而技术人员的储备速度远远跟不上IT系统的发展速度。我们很欢迎你这样的年轻人。”
我并没有感到意外，和顾总第一次见面就感觉她是一个十分敏锐的人。不过如何拒绝顾总的邀请呢？我考虑了一下回答说，顾总，其实你和我们公司签一个长期合作协议，那么包括我在内的一批技术骨干就可以为你们服务了，而且你对我们的管理是甲方对乙方的方式，比管理自己的职工更为有效。
我正和顾总推销我们的服务，餐馆已经到了。分宾主落座之后，老雷一坐下来就问今天喝点什么酒，白的还是红的？
谢总今天明显心事重重，干脆喝点脾的吧，明天问题搞定了好好喝一下。
老雷说小白都出手了，肯定没问题，明天一定搞定。
谢总一听马上来了精神，小白怎么样？今天的问题能定位吗？
我说虽然今天的实验没有达到我的预期，不过起码证明了LINUX的虚拟内存管理机制存在问题，可能出现瞬间的大规模换页，从而诱发故障。以前我碰到过一个Oracle RAC的BUG，就是由于换页导致实例被错误的驱逐了。这个BUG虽然是9i的，不过在10G上也有可能存在类似的问题。从日志分析上目前还看不到其他BUG的迹象。
老雷举着酒杯说老谢咱们先干一杯，这个问题一定能解决，你就把心放到肚子里吧。小白的能力我是绝对信任的。其实我和老雷也是第一次见面，这个项目是通过一个中间人介绍过来的。不过老雷天生豪爽，颇有点东北人的脾气。
老雷和谢总干了一杯。然后又去敬顾总，顾总果然巾帼不让须眉，也不推辞，当即和老雷干了一杯。我知道下一个老雷是要和我喝了，干脆主动举杯说，老雷，我们第一次喝酒，敬你一杯。
谢总在旁边说，老雷是海量，你们搞人海战术没用，明天我们喝点白的，否则喝脾的干不倒他。
喝了一轮，气氛也热烈了起来，大家也聊性大开。在座的除了老雷都是搞技术出身的人，一起大倒做IT的苦水。就像现在碰到的莫名其妙的宕机一样，经常会碰到一些解释不清的问题。谢总说几年前他在另外一家证券公司，当时的UPS系统总是出问题，厂家维修了无数次，也解决不了问题。后来他把一个从五台山带回来的小铜狮子放到那个UPS上以后，这个UPS就不出问题了，到现在还用的好好的。后来谢总离开那家券商的时候，接任的人说老谢，其他东西你都可以拿走，就是那个狮子不许带走。
于是大家就打趣说谢总，干脆明天你再去串个门，趁机把那狮子偷回来，往服务器上一镇，也许就把我们的问题解决了。今天大家都有些心事，所以喝了不到一个小时就散了。不过一看表，也已经10点多钟了。还好我住的酒店离这边不远，步行了不到10分钟就到了。
回到酒店，我马上打开了下午下载的那几个BUG认真看了起来，突然一个编号为6072385的BUG报告引起了我的注意，ORA-29740 - IPC SEND TIMEOUT - BROKEN PIPE (32) ：
PROBLEM:
--------
Ct facing periodics 'ipc timeout' problems at DB level which leads to node
Evictions
2 node environment running RedHat EL4 on x86_64 (2.6.9-42.0.8.ELsmp)
- chsduo107: (Inst:duodb1)
- chsduo108: (Inst:duodb2)
Wed May 23 19:38:45 2007
IPC Send timeout detected.Sender: ospid 8369
Receiver: inst 2 binc 469974830 ospid 25136
Wed May 23 19:38:46 2007
Errors in file /opt/oracle/obase/admin/duodb/bdump/duodb1_s001_8369.trc:
ORA-27508: IPC error sending a message
ORA-27300: OS system dependent operation:sendmsg failed with status: 32
ORA-27301: OS failure message: Broken pipe
ORA-27302: failure occurred at: sskgxpsnd1
Wed May 23 19:38:46 2007
IPC Send timeout to 1.2 inc 112 for msg type 32 from opid 20
Wed May 23 19:38:46 2007
Communications reconfiguration: instance_number 2
Wed May 23 19:38:46 2007
Trace dumping is performing id=[cdmp_20070523193846]
Wed May 23 19:40:27 2007
Waiting for clusterware split-brain resolution
Wed May 23 19:50:27 2007
Evicting instance 2 from cluster
Wed May 23 19:50:32 2007
Trace dumping is performing id=[cdmp_20070523195032
Cssd的日志内容为：
[ CSSD]2007-06-15 09:09:06.067 [1157658976] >TRACE:
clssgmClientConnectMsg: Connect from con(0x8e8e10) proc(0x8ec380) pid()
proto(10:2:1:1)
[ CSSD]2007-06-15 09:09:06.181 [1157658976] >TRACE:
clssgmClientConnectMsg: Connect from con(0x8e8e10) proc(0x8ec430) pid(22341)
proto(10:2:1:1)
[ CSSD]2007-06-15 09:09:24.854 [1157658976] >TRACE:
clssgmClientConnectMsg: Connect from con(0x8ec0a0) proc(0x8ef630) pid()
proto(10:2:1:1)
[ CSSD]2007-06-15 09:10:25.124 [1157658976] >TRACE:
clssgmClientConnectMsg: Connect from con(0x2a97a3f8f0) proc(0x2a97a59640)
pid() proto(10:2:1:1)
[ CSSD]2007-06-15 09:11:11.423 [1189128544] >TRACE: clscsendx:
(0x2a97a462e0) Connection not active
[ CSSD]2007-06-15 09:11:11.423 [1189128544] >TRACE: clssgmSendClient:
Send failed rc 6, con (0x2a97a462e0), client (0x2a97a467e0), proc ((nil))
[ CSSD]2007-06-15 09:11:11.512 [1189128544] >TRACE: clscsendx:
(0x2a97a3b480) Connection not active
[ CSSD]2007-06-15 09:11:11.512 [1189128544] >TRACE: clssgmSendClient:
Send failed rc 6, con (0x2a97a3b480), client (0x2a97a3bdf0), proc ((nil))
[ CSSD]2007-06-15 09:11:11.512 [1189128544] >TRACE: clscsendx:
(0x2a97a3c170) Connection not active
[ CSSD]2007-06-15 09:11:11.512 [1189128544] >TRACE: clssgmSendClient:
Send failed rc 6, con (0x2a97a3c170), client (0x2a97a3c470), proc ((nil))
[ CSSD]2007-06-15 09:11:11.553 [1189128544] >TRACE: clscsendx:
(0x2a97a3c7f0) Connection not active
[ CSSD]2007-06-15 09:11:11.553 [1189128544] >TRACE: clssgmSendClient:
Send failed rc 6, con (0x2a97a3c7f0), client (0x2a97a3caf0), proc ((nil))
[ CSSD]2007-06-15 09:11:12.644 [1157658976] >TRACE:
clssgmClientConnectMsg: Connect from con(0x2a97a0dc40) proc(0x2a97a4bef0)
pid() proto(10:2:1:1)
[ CSSD]2007-06-15 09:11:12.651 [1157658976] >TRACE:
clssgmClientConnectMsg: Connect from con(0x2a97a16130) proc(0x2a97a493a0)
pid() proto(10:2:1:1)
[ CSSD]2007-06-15 09:11:12.846 [1157658976] >TRACE:
clssgmClientConnectMsg: Connect from con(0x2a97a10e70) proc(0x2a97a0e8d0)
pid() proto(10:2:1:1)
[ CSSD]2007-06-15 09:11:12.855 [1157658976] >TRACE:
clssgmClientConnectMsg: Connect from con(0x2a97a3ede0) proc(0x2a97a3e380)
pid() proto(10:2:1:1)
[ CSSD]2007-06-15 09:11:12.876 [1157658976] >TRACE:
clssgmClientConnectMsg: Connect from con(0x2a97a0dc40) proc(0x2a97a4b250)
pid() proto(10:2:1:1)
[ CSSD]2007-06-15 09:11:13.068 [1157658976] >TRACE:
clssgmClientConnectMsg: Connect from con(0x2a97a0dc40) proc(0x2a97a0bbf0)
pid() proto(10:2:1:1)
[ CSSD]2007-06-15 09:11:16.520 [1189128544] >TRACE: clscsendx:
(0x2a97a2e860) Connection not active
[ CSSD]2007-06-15 09:11:16.520 [1189128544] >TRACE: clssgmSendClient:
Send failed rc 6, con (0x2a97a2e860), client (0x2a97a12d40), proc ((nil))
[ CSSD]2007-06-15 09:11:16.520 [1189128544] >TRACE: clscsendx:
(0x2a97a2edc0) Connection not active
[ CSSD]2007-06-15 09:11:16.520 [1189128544] >TRACE: clssgmSendClient:
Send failed rc 6, con (0x2a97a2edc0), client (0x2a97a2f0c0), proc ((nil))
[ CSSD]2007-06-15 09:11:16.560 [1189128544] >TRACE: clscsendx:
(0x2a97a27850) Connection not active
[ CSSD]2007-06-15 09:11:16.560 [1189128544] >TRACE: clssgmSendClient:
Send failed rc 6, con (0x2a97a27850), client (0x2a97a28910), proc ((nil))
从OSW的监控信息中，也发现了物理内存不足20M，以及宕机前突然出现了sys占用CPU较高的现象。这一切都和我们这个案例十分相似。而这个案例也是通过调整了VM的参数来解决问题的：
o.s. parameter change have made system much more stable - no re-occurrences
for last month.
vm.swappiness = 80
vm.vfs_cache_pressure = 200
不知不觉已经12点多了，阅读了10多个BUG报告，感觉还是很有收获，我更加坚定了今天的推测。还是早点睡吧，明天是决定性的一天。
4.3. 3月4日 决定
昨天晚上虽然只喝了一瓶多啤酒，不过对于我来说还是有点多，回到酒店后，我翻看了几份BUG报告，又从METALINK上搜索到了几份文档，看了一会已经是临晨1点了，明天将是艰苦的一天，所以今天不能太晚睡觉了。我一般来说喝了酒，睡眠就不好，虽然睡得挺晚，不过早上不到七点钟就醒了。醒来后我还是在想这个奇怪的宕机，为什么总是第一台服务器宕机呢？而且从操作系统监控的信息来看，第二个节点总是有超过1g的物理内存空闲，是不是由于什么应用引起的呢？吃过早饭才七点半钟，于是又打开电脑看了看昨天晚上没有看完的文档。这些BUG包括BUG 6161776，6411744， 6007304，5493367，6513829， 6681511， 6437235， 6841973， 5566127，6072385。大多数BUG从现象上来看和这个案例都有些类似，不过仔细分析一下，除了6072385外，其他BUG都有些解释不清的东西。6072385最后被确认为不是一个BUG，而是操作系统的问题，这确实和我昨天的怀疑十分接近。
早上和小陈聊了聊，我才知道这个系统的一些情况，这套RAC系统两个节点上跑的应用是不同的，一套处理针对散户的交易，一套处理针对机构的交易。除了上面的区别外，在一号节点上还跑了一个DSG的数据复制软件，用于做容灾复制。DSG复制的机制是通过REDO LOG捕获数据库的变化矢量，然后将变化矢量组织成文件暂存在本地，再将文件传输到容灾平台。在这个过程中，存在大量的文件IO操作，这样一来，在1号节点上使用大量的BUFFER/CACHE，并且空闲内存较少，而2号节点上总是有超过2g 的空闲内存就解释的通了。
我和小陈正在聊着，谢总走了进来，见到我就问是不是有新的进展。我说昨天晚上我又查找了一些资料，发现了和这个案例基本类似的BUG报告，数据库的版本和CRS版本基本上是一致的，表现出来的现象也类似。那份报告的结论也是由于系统换页导致节点被驱逐。
谢总听了很高兴，他楞了一下说，昨天晚上喝了酒你回去还干活啊，就看你这种认真，这个问题你一定能解决。
今天上午的主要安排就是在监控室对一号节点的虚拟内存情况进行监控。由于昨天晚上重启过服务器，因此刚开始的时候，物理内存的空闲还有3个多G，开市后，不过到了10点多钟，物理内存的空闲空间就不足1G了。上午收市的时候之后，物理内存略微有些恢复，大概有1g多点。通过free命令可以看到buffer和cache都增长了很多。从目前我能够分析到的信息来看，目前的唯一怀疑点都集中到了系统发生换页的问题上，其他的十多个BUG都基本上被排除了。不过调整虚拟内存的参数真的能解决这个问题吗?我的心里也在打鼓，这种案例是我从来没有遇到过的，如果不是由于虚拟内存参数引起的，那么对客户来说，这个炸弹并没有被排除。
午饭后，我又查了查sr的信息，oracle gcs那边又有了新的更新：
data collected
--------------------
1. alertyhshsec2.log
2008-03-03 14:02:08.966
[cssd(16573)]CRS-1607:CSSD evicting node yhshsec1. Details in /oracle/crs/log/yhshsec2/cssd/ocssd.log.
2. ocssd.log node2
[ CSSD]2008-03-03 14:01:39.949 [1241577824] >WARNING: clssnmPollingThread: node yhshsec1 (1) at 50 1.482197e-3
23artbeat fatal, eviction in 29.010 seconds
3. ocssd.log node1 don't contain any info from the eviction
[ CSSD]2008-03-02 14:06:08.730 >USER: Oracle Database 10g CSS Release 10.2.0.3.0 Production Copyright 1996, 2004 Oracle. All ri
ghts reserved.
[ clsdmt]Listening to (ADDRESS=(PROTOCOL=ipc)(KEY=yhshsec1DBG_CSSD))
time node1 after reboot 2008-03-02 14:06:11.57 = time node2 2008-03-03 14:06:00
time node1 before reboot 2008-03-01 11:16:05 = time node2 2008-03-01 11:15:47 (+18s)
=> so node2 detect node1 as down at 14:01:39-30s+18s or 14:01:27 node1 time.
4. oswatcher node1
zzz ***Mon Mar 3 13:59:55 CST 2008
procs -----------memory---------- ---swap-- -----io---- --system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
9 1 211000 21204 14008 6038548 0 0 55 27 2 2 1 1 98 0
0 0 210952 20040 14068 6038400 136 0 3149 1740 4482 11000 5 4 90 1
0 0 210948 20032 14076 6038396 0 0 51 417 4430 11952 4 1 94 0
zzz ***Mon Mar 3 14:00:15 CST 2008
procs -----------memory---------- ---swap-- -----io---- --system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
24 0 204360 14768 7592 6056904 0 0 55 27 2 2 1 1 98 0
4 4 204360 16464 5196 6056248 0 0 9411 414 4064 5694 8 70 16 5
0 8 204284 15608 2720 6056704 188 0 20581 1986 6160 11735 8 30 49 13
=> cpu high due to systemcall time. oswatcher could not work anymore 52 before node2 start to
detect node1 as evictable.
=> top could not be execated at Mon Mar 3 14:00:15
=> no io activity, network was pingable
5. message log filess
Mar 3 09:41:35 yhshsec1 sshd(pam_unix)[5926]: session opened for user root by root(uid=0)
Mar 2 14:04:41 yhshsec1 syslogd 1.4.1: restart.
6. no ocfs2 or ocfs used
Oracle gcs那边也发现了sys CPU过高的问题，不过他们并没有怀疑是否出现了大量的换页操作，而只是建议打一个补丁：
Hi
Luckily, we have the oswatcher on the right node.
It looks the nodes are most of the time idle. At Mon Mar 3 14:00:15, we see an abnormal surge
of syscall activity via vmstat. syscall usage never reach 15% in any forwarded oswatcher d
ate and
it was 70%, 30% at once. There are no new processes started either. OSwatcher is blocked afterwards.
node2 start to detect node1 is down a minute latter and the eviction of node1 occured 2min later.
Please install the patch:5679560 (see note:5679560.8). It will update the init* files with scripts that are more
robust agains sporadic cpu shortages, i.e. they don't trigger a potentially unnecessary reboot due
to bug:5679560. They can also log something more in case of problems in the /var/log/messages
Please keep collecting the oswatcher data afterwards for a while (in case of).
PATCH 5679560修复了一部分crs的脚本上的BUG，使CRS变得更为稳定。不过这个系统已经安装了PATCH 6160398 ,我分析了一下PATCH 6160398 ，发现其中已经包含了PATCH 5679560，这个建议明显是不合理的。看样子ORACLE GCS那边是指望不上了。我和小陈讨论了一下，决定采取下面的措施：
首先调整3个虚拟内存参数:
- vm.min_free_kbytes=409600
- vm.vfs_cache_pressure=200
- vm.swappiness =40
调整MIN_FREE_KBYTES的目的是保持物理内存有足够的空闲空间，防止突发性的换页。Swapiness缺省为60，减少swapiness会使系统尽快通过swapout不使用的进程资源来释放更多的物理内存。Vfs_cache_pressure的缺省值是100，加大这个参数设置了虚拟内存回收directory和i-node缓冲的倾向，这个值越大，回收的倾向越严重。调整这三个参数的目的就是让操作系统在平时就尽快的回收缓冲，释放物理内存，这样就可以避免突发性的大规模换页。
顾总和刘工上午去拜访了他们的客户，中午回来的时候我和小陈刚刚制定好调整方案。于是我和小陈向顾总、谢总汇报了今天下午调整操作系统参数的计划。他们对我们的方案表示支持，不过为了保险起见，顾总建议目前暂时只调整1号节点，如果调整了2个星期后，发现确实有效果，再调整2号节点。参数调整安排在下午5点开始。
方案确定后，谢总还是有点不放心，问我调整这几个参数会不会影响系统的性能？我考虑了一下说，根据我的经验，这不应该影响系统性能，如果有影响也是十分微小的。
虽然我比较明确的说这些参数调整对他们的系统几乎不会出现任何性能影响，不过为了安全起见，我还是建议调整参数前后，在2个节点上各做10分钟左右的压力测试，通过AWR报告来分析是否对系统性能有影响。
确认了调整方案后，我再一次表示，这仅仅是目前我觉得最有可能出现问题的地方，调整后，相关的监控，包括OSW的采集不能停，而且METALINK上的那个服务请求也要继续更新，最好今天就把我们要做的事情贴上去，看看ORACLE GCS那边是什么态度。
今天下午的操作系统参数修改操作由开发商的小陈实施，我和刘工在旁边协助。在修改参数之前，我们需要采集参数修改前系统的平均事务响应时间。所以小陈搭好了昨天的那个测试环境，准备做10分钟的压力测试，为了参数修改前后两次测试的数据完全一致，我建议两次用的表内的数据全部按照刚开市的时候的设置，通过awr报告来看，修改参数前的压力测试采样时间10.9分钟，平均事务响应时间为7.96毫秒。
参数修改前的平均事务响应时间采集完毕后，我们就开始修改linux的参数了。首先我们sysctl命令调整了三个参数：
#sysctl -w vm.min_free_kbytes=409600
#sysctl -w vm.vfs_cache_pressure=200
#sysctl -w vm.swappiness=40
参数修改完毕后，进入/proc/sys/vm目录，检查这三个参数是否修改正确：
#cd /proc/sys/vm
#cat min_free_kbytes
#cat vfs_cache_pressure
#cat swappiness
参数修改完毕后，过了几分钟，1号节点上的空闲物理内存明显回升。说明参数确实起作用了。上面的操作完成了对目前系统的调整，永久性的设置需要修改/etc/sysctl.conf参数文件。
cd /etc
#cp sysctl.conf sysctl.conf.save20080304
#vi sysctl.conf
添加如下内容：
#modify vm parameter
vm.min_free_kbytes=409600
vm.vfs_cache_pressure=200
vm.swappiness =40
修改完毕后，刘工建议重启一下1号节点，确认参数修改没有问题。10分钟后服务器重启完毕，通过检查/proc/sys/vm下的相关文件，发现参数修改正常。下一步就要确认操作系统参数修改后是否对应用软件的性能产生影响的问题了。为了保证和参数修改前的测试环境一致，数据库再次恢复到了刚开市的状态。然后用刚才相同的压力测试脚本对系统进行测试。AWR报告的采样时间为11.59分钟，经过计算，平均事务响应时间为8.13毫秒。从平均事务响应时间来看，参数调整前后差别不大，可以说这次参数调整对系统的性能基本上没有多大的影响。
参数调整完毕，我们刚刚走出机房，看到老雷正在外面和顾总谢总聊天。看到我们出来，老雷兴高采烈的问我，怎么样小白，搞定了吗？
我说参数已经调整完毕了，从性能测试结果来看，参数调整对系统性能没什么影响。至于是不是已经搞定了，我还不敢说，因为目前只是排除了一个最大的可能性。如果要说是不是搞定了，我只能说保守的估计，有七八成把握吧。
谢总在旁边大手一挥，肯定搞定了，昨天我听你说那个AIX上的BUG，就感觉很相似，今天又有一个环境一模一样的案例，肯定就是这么回事了。
老雷在旁边接着说，那当然了，小白出手了，肯定没错，保守估计是七八成，那么乐观估计有八九成，也就八九不离十了。行了，今天大家多喝点，庆祝庆祝，这个破事终于搞定了。
晚上还是在昨天吃饭的地方，老雷点了一桌丰盛的上海本帮菜，还点了一瓶五粮液。大家推杯换盏，喝完了白的喝脾的，气氛十分热烈。老雷和谢总坐在一起，不知道老雷怎么惹到谢总了，谢总突然说老雷你再这么不够意思，我把你手下那帮小伙子全部挖过来。现在大市这么好，我们出30万年薪挖你几个人还是挖的起的。于是大家开始为30万年薪起哄。
一直话不多的顾总突然发话了，小白，昨天我说的事情你有没有兴趣？我们很需要你这样有责任心的年轻人，有什么要求你尽管提。我只好把昨天的关于如果我们有合同，包括我在内的一个团队都可以为他们服务的话重复了一遍。顾总看我态度比较坚决，就说那好吧，有空到北京我们谈谈长期合作的问题。
由于今天我的态度比较坚决，所以大家对今天能否解决问题都有着比较乐观的态度，晚饭的气氛一直很不错。谢总是这个项目的直接责任人，这段时间为了系统不稳定的问题，很久没有睡过好觉了，今天按照他的意思是喝个痛快，然后回家睡个好觉。他和老雷的酒量都不错，喝完啤酒，每个人又干了几瓶啤酒，大家才尽兴而归。
回到酒店，我马上登陆METALINK看看GCS有什么反馈。自从GCS移到印度后，对中国的响应速度大大提高了，一般来说一个二级的TAR在2个小时内就会有响应。我们在TAR上的回复，在8小时内基本上就可以看到GCS的回复。打开文档一看，确实已经有了回复：
Hi
The default swappiness is 60. This works well if we want to swap out daemons or programs which have not done much recently.
The default value for swappiness is 60 with is appropriate for regular workloads.
While tuning this parameter keep in mind that higher values will provide more buffer/page cache and lower values will wait longer to swap out idle processes. If there is too much memory that
is free memory and you suffer from swap-outs (from vmstat), then lowering swappiness can help. Setting swappiness close to 0 (<10) is something you can do when you have really enough memory (e.g. 4GB SGA and 32GB RAM) to be able to handle some immediate large memory requirements that can arise during some peek time.
=> i would suggest to keep the swappiness to 60 in your case. We don't see a big swapout activity in the vmstat.
The value min_free_kbytes should indeed be set to something like 400000 ... 500000 (see note:452000.1) and can have an influence on the reboots.
I have no data/observation about vm.vfs_cache_pressure.
Basically, patch:5679560 contains new init* scripts. The purpose is that a potential (not expected, but happening) respawn
of inittab scripts (it can happen when the system is under load) don't cause a crash of the running ocssd.bin process,but just end up with no consequences.
看来GCS的哥们对我今天调整的三个参数持保留态度。对于日志的分析，他又给出了一些回复：
The last one show typically a OS problem when we have plenty of system cpu usage. The ocssd don't show
any messages (just ocssd on node2 that detect node1 is not responding).
So, it just can be that both reboots have the same reason when the temporal hang on node1 la
st a bit longer on node1 in the second case than in the first case and that the hangcheck-timer or oomkiller kills some fatal processes.I would set the diagwait to 13 on those systems, via
crsctl set css diagwait 13
=> it will permit that a reboot like on 22feb will occur a bit latter when the node is evicted.
It means that the oswatcher could collect some additional info just before the reboot since the machine seems to start working again after a while.
他也观察到了操作系统出现了一些异常，不过并没有把怀疑目标指向系统换页，而且对我调整这几个操作系统参数持保留态度。不过对于GCS的回复，我觉得其参考价值并不大，由于缺少部分日志信息，因此那个印度哥们一直拒绝做出较为明确的推断，这一点实际上也说明了Oracle的技术人员十分专业，宁可不做评价，也不能做错误的评价。对于ORACLE GCS的工程师，他完全可以这样坚持原则，而对于我们，就必须冒险了，如果我们也像ORACLE原厂的支持人员一样，就很难在这种夹缝中生存了。
今天的参数调整虽然做了，不过我心里还是有点不踏实，这个问题是不是真的解决了呢？我心里都没有什么把握。所以我应该向客户提出以下几条建议：
- 继续跟踪系统，osw还需要开着，如果观察1、2个月，系统没有再次宕机，那么就说明问题真的解决了。
- Metalink上的tar还需要继续跟踪，有什么信息及时更新，在1个月内不要让tar关闭了
- 如果还发生宕机现象，那么下一个值得怀疑的对象是dsg，建议将dsg移到2号节点上去跑，看看是不是还是1号节点宕机
4.4. 3月5日 平安无事了
由于昨天做了参数调整，所以今天不到9点钟，我和小陈都来到了监控室，打开了各种监控界面。今天一大早顾总和刘工就回北京了，谢总去机场送她们两个。对于我来说，这个项目目前也算是告一段落，如果今天系统一切正常，那么就要看最近这一个月内是否还会出现宕机的现象。从今天早上的情况看，开市以后，随着系统负载的增加，物理内存并没有向以前那样大幅度的下降，一直保持着2G多的空闲。目前1号节点物理内存的空闲比例比2号节点还略高一些。这说明昨天的参数调整对于虚拟内存的管理是有相当大的改变的。从小陈那边对应用的监控来看，应用系统性能正常。实际上调整VM的参数不应该对应用产生多大的影响，这也是我们意料中的事情。
我和小陈一直在监控室里观察，直到中午休市。从今天的系统情况看，CPU使用率一直在8-9%，空闲内存一直保持2G以上，IO也没有发现任何异常，系统运行十分平稳。于是我们两个就找到谢总，向他汇报了上午的情况。
“谢总，系统比较平稳，我准备下午回深圳了，有什么问题电话联系。我今天的航班是下午4点10分的，如果你们休市前有任何异常，都可以打电话给我。问题的分析报告需要1、2天时间来整理，本周内发给小陈。”
谢总今天的精神状态明显比昨天要好，他笑着说小白，真希望你能多留几天，不过你留的时间长了，老雷就要吐血了，所以我就不留了。不过我们后续还要做什么，你最好能和小陈交代一下。
我说，其实也没什么。这次我只能说是消除了一个宕机隐患，是否有效还需要观察半个月到一个月。所以METALINK上的那个tar一定要保持开放状态，并及时和GCS交流采集到的日志。OSW最好一直开着，只要定期清理一下历史数据就行了。哪怕这个问题用不着OSW的数据了，今后碰到其他问题还是用得着的。开OSW的系统开销不到1%，不会对你们的系统有什么影响。
中午谢总提出一起吃个工作餐，我说这回就算了算了，谢总你也需要好好休息一下，等下回有机会再说。
谢总听我这么说马上摇头，说：“小白，虽然你很不错，不过最近我不想见到你了。”
我明白他的意思，笑笑说下回我到上海给招商证券解决问题还不行，到了上海肯定要到你这里来蹭饭。
浦东隧道经常堵车，所以我提前了三个多小时出发。没想到今天异常的顺利，不到半个小时就到了虹桥机场。现在还没开始换登机牌，到处转了转，也没有发现什么可以休息的地方。抬头看见旁边的一个自助餐厅，才想起来刚才拒绝了谢总的饭局，午饭还没吃呢。五十八元的自助餐，确实很一般，不过在机场能够有这样的价钱算是很便宜了，况且还可以无线上网。想想要在餐厅里等一个多小时才开始换登机牌，这顿饭确实需要慢慢吃了。我吃饭向来比较快，一般来说都会在10分钟以内解决问题，哪怕是吃自助餐也很少能吃上二十分钟的。于是我先拿了一盘水果，先开开胃再说吧。
本来觉得时间会很难熬，不过一上网就遇到事情了。刘工已经回到了北京，她刚到办公室就收到了一份报告。原来他们把2号系统故障的日志也发给了一家做Oracle咨询方面的公司，他们公司也根据日志写了一份问题分析报告。刘工说按照报告的内容来看，他们公司对问题的定位很明确，并且提出了解决方案。因为我这次对问题的定位并不是百分之百的确定，所以刘工也很担心，是不是我并没有彻底解决问题。我说那份报告是否方便给我看看，你可以隐去对方的名字，只把关键的分析发给我，也许真的有一些很不错的建议呢。
刘工犹豫了一阵，最后还是把删节后的报告发给了我。他们认为故障是由于两台服务器时间不同步导致的，以下是分析报告的部分内容：
这个日志看来似乎正常，但结合alert日志和CRS日志一起分析，就可以得出结论：在这段时间内，CSS服务因失败而rebooting了，证据是clssnm_skgxnmon: skgxn init failed：和clssnm_skgxnonline: Using vacuous skgxn monitor这两条记录。
根据clssnm_skgxnmon: skgxn init failed这一条记录，到Oracle的《knowledge Base》查询，就有了惊人的发现：
在Oracle的Knowledge Base中有相同的案例，并且失败时的日志是一样的。从日志中发现，系统时钟已经被修改过，在修改系统时钟后(精确地说，是修改前后的时差超过1.5s之后) Oracle 10g RAC clusterware会自动让服务器rebooting。 详细机制参见Internal Only的《Metalink Note 308051.1》。以下是这篇文档的摘录：
The OPROCD executable sets a signal handler for the SIGALRM handler and sets the interval timer based on the to-millisec parameter provided. The alarm handler gets the current time and checks it against the time that the alarm handler was last entered. If the difference exceeds (to-millisec + margin-millisec), it will fail; the production version will cause a node reboot.
我们建议，在未来运行中，可以尝试修改/etc/init.cssd中关于OPROCD（Clusterware的一个设置参数）的配置，将DISABLE_OPROCD设置为TRUE，然后重启系统，这样可以避免故障发生。 否则，即使系统进程中已经不存在oprocd进程，但在修改完系统时间后，服务器仍会被重启。
Oracle该文档中另外的描述提到，如果OPROCD是在non fatal mode状态下启动的，那么将只会写一段log而不去重启机器。另外，Note:265769.1也描述了如何修改为non fatal mode的方法。
如果需要，我们可以通过模拟的方式再现该故障的发生过程，但是我们目前还没有尝试该操作。
In fatal mode, OPROCD will reboot the node if it detects excessive wait. In Non Fatal mode, it will write an error message out to the file
建议 ：将整个cssd进程disable掉，这样可以避免因为修改系统时间而引起服务器重启。
......
四．总结
该系统的时钟被修改，可能是手动的。
在系统修改时钟后，由于改变量（时差）超过了1.5s，导致Oracle Clusters的一个节点Node1自动reboot服务器。
在服务器reboot和Oracle重启之后，RAC两个实例运行正常。
但在服务器reboot过程中和RAC Clusters reconfigure的过程中（也即，在node2没有完成reconfigure之前），node1处于宕机状态。此时，若中间件（进行随机的负载均衡）将负载传送到节点node1上执行，可能导致连接数据库的部分应用终端不可用，造成部分业务停止。
五．建议方案
第一方案，
如果修改Oracle 10g RAC某节点的系统时间量超过1.5秒，且RAC Cluster采用fatal mode，则这个节点具有被自动重启的机制，从而造成业务故障。
建议：若非必须，绝不要随意地（特别是在业务发生期间）修改服务器OS的时钟。
另一个方案，
将RAC配置成non fatal mode。在这种模试下启动的RAC Clusters，将只会写一段log，而不去重启服务器。修改non fatal mode的方法见Oracle Knowledge Base Note:265769.1。
这份报告在刘工收到之前，公司里的人已经咨询过几个资深的DBA，他们都觉得分析很透彻，值得重视。不过我粗一打眼就觉得这份报告里有很大的问题，时间不同步的问题我也曾怀疑过，不过后来发现时间误差只是一个误会，报告里所提的那个BUG我也曾分析过，因为目前在10.2.0.3 BUNDLE PATCH 1以后这个BUG已经解决了，所以也早就被我排除了。更为重要的是，这个系统是linux系统，根本就不存在OPROCD，在LINUX环境下，是通过HANGCHECK-TIMER机制来实现OPROCD的功能的，而没有使用OPROCD。从最后的建议方案来说，两个方案也没有任何的依据。在non fatal mode下运行软件当然可以避免节点reboot，不过并不能解决由于节点驱逐导致的数据库宕掉。而且non fatal mode一般情况下只是在诊断故障过程中作为临时手段使用，并不是一个常规运行的对可用性要求十分高的系统应该使用的常规手段。
拿到这份报告后我感觉到长出了一口气，原本我还在为如何向刘工做出合理的解释犯愁。因为技术这东西，你可能十分清楚，不过要让别人相信你是对的，还是有难度的，特别是在有第三方的意见的情况下。而这份报告上的两个致命的缺陷让我很容易解释，一个是那份报告上没有明说的那个BUG，实际上我是分析过的，发生在AIX平台上，不过这个问题在10.2.0.3的PATCHSET里已经解决掉了，并且在LINUX平台上并不存在OPROCD。
刘工听了我的分析后十分感慨，她也是今天才拿到这份报告的，刚才阅读完这份报告，她觉得写这份报告的人水平很高，整个报告抽丝剥茧，层层深入，一环套一环，而且关键的地方都引用了Oracle的官方文档。特别是这份报告中的使用的是统一的肯定语气，让人不得不信服。而我写的问题分析报告，里面用了大量的推测，并且最终的结论是一个月之内没有出现类似的宕机故障，才确认问题彻底解决了。所以她和公司领导看了那份报告后还是觉得心里不踏实。看完这份报告后，她甚至对我的处理过程产生了怀疑，觉得我做的调整是不是能够真正的解决问题，不过由于两方面都是专家，她也无法判断到底谁是正确的，如果直接问对方又感觉不知如何出口。所以她联系我之前犹豫了很久，刚才也和谢总交换了意见，谢总对我表示了充分的信任，并建议她直接和我沟通这件事。
我说做技术的，必须实事求是。这个问题确实不能100%定位，所以报告里肯定只能这么写。只有这样，大家才能保持警惕，各种监控手段都还保留，一旦问题并没有解决，那么下一次出现故障的时候，我们可以获取更多信息，为最终解决问题提供资料。如果我现在在报告里写的十分肯定，现在你和你们领导倒是踏实了，不过如果问题没有解决，下次宕机的时候大家一点思想准备也没有，那么损失就更大了。我不希望发生这种事情的时候挨骂，只能现在让大家不够踏实了。刘工听了我的话，思考了很久，说了一句话：“技术骗子危害不小啊”。
处理完这件事，已经4点多了，刚才拿的一盘水果还没吃完。匆匆忙忙吃了点点心，就急忙跑过去办登机牌了。一路小跑赶到登记口的时候，登机口已经空空荡荡的，工作人员正拿着话筒呼叫着最后几个登机的人员。看过下午的那份分析报告，我更加自信这个问题已经搞定了。
4.5. 后记
DBA日记第二部的模式和第一部有所不同，在每个短小的案例结束的时候，都会有一段后记。后记的目的是交代在日记中没有交代清楚的事件，并且对这个案例做一些总结性的回顾。
上海的这个RAC节点被驱逐的故障已经过去快一年了。那个系统自从调整了操作系统参数后一直保持十分稳定，没有再次宕机。实际上在4月份小陈就很自信的关闭了METALINK上的那个SR。这次优化工作的另外一个收获是认识了一些朋友，而且几个月后我们成为那个客户的签约合作伙伴。
从这个案例里，有几点可以和大家探讨一下。如果我问大家这个案例成功的要素是什么？可能有很多种回答，碰到过类似案例是一个方面；对操作系统比较熟悉是一个方面；分析故障的方法是一个方面；还有很多其他的答案。不过我觉得这些都不是最关键的，这个项目成功的最大原因是责任心。这是一个十分复杂的案例，如果这个案例最后被GCS的技术人员解决，这是比较正常的，因为GCS那边可以找到很多类似的案例，而且他也已经发现了操作系统的异常。而最终的结果是在GCS的人还没有摸到门的时候，老白似乎很幸运的找到了一个类似案例，并赌博成功，解决了问题。难道老白拥有的仅仅是幸运吗？其实老白在到现场之前，就已经认真分析了所有的日志，并且阅读了十多个类似案例，排除了大量可能的情况，而且阅读了大量关于crsd,cssd方面的资料。第一天晚上大家喝完酒回到酒店，老白还继续查阅案例，终于发现了一个十分相似的BUG报告，这确实是十分难得的。做服务的人每年都会遇到很多客户，在每个案例上都这么投入，对于绝大多数人来说是很难做到的。老白的信念是我们要对得起自己的手艺，因此对待每个案例，每个客户，老白都会以这种负责的态度去对待。米卢曾经说过一句话“态度决定一切”，用在这个案例上十分贴切。由于老白负责的态度，最终获得了客户的信任，解决了问题。老白的责任心还表现在对待技术问题的态度上，这和结尾时候的那份分析报告形成了鲜明的对比。实际上类似的分析报告老白见过很多，这些报告可能能够一时蒙蔽客户，达到某些商业目的。不过这种假行家的报告危害性是很大的，不仅仅对客户，对写报告的人本身也是这样。做IT服务的人，最关键的是信用，一旦失去了客户对你的信任，那么就意味着失去了一切。
4.6. 本章技术要点讲解
处理RAC宕机故障一直是DBA的难点所在，RAC系统涉及的环境较为复杂，主机、存储、网络、数据库、第三方CLUSTERWARE，甚至包括CLUSTER文件系统等。由于这些东西组件本身就十分复杂，放在一起就更为复杂了。碰到RAC带的故障如何去分析和处理呢？
首先我们来看看，做一个RAC宕机分析所需要的资料：
- 数据库的ALERT LOG（两个节点）
- 数据库的SMON,PMON,LMS,DIAG,LMON,LMD等后台进程的日志（两个节点）
- CRS日志（10G或者以后版本），包括crsd,ocssd,evmd等的日志（两个节点）
- 操作系统日志（syslog,message等）
- 数据库宕机前后的statspack报告（如果能找到，对于10g ,awr报告、ash报告、addm报告等都对分析有帮助）
- 宕机前后的操作系统监控数据
- udump下的相关trace文件
在有条件的情况下，可以使用rda来采集上述信息。信息采集完毕后，就需要对采集的信息进行分析。分析宕机故障的时候，我们首先应该看看alert log中在宕机前的信息，一般情况下，大多数宕机的现象是可以看到一些异常现象的，比如：
Tue Apr 1 10:54:05 2008
Errors in file /oracle/admin/zhjs/bdump/zhjs2_lmon_10634.trc:
ORA-00600: internal error code, arguments: [kjrfr:!owner], [0xC000000156DA8F48], [], [], [], [], [], []
Tue Apr 1 10:54:34 2008
Errors in file /oracle/admin/zhjs/bdump/zhjs2_lmon_10634.trc:
ORA-00603: ORACLE server session terminated by fatal error
ORA-00600: internal error code, arguments: [kjrfr:!owner], [0xC000000156DA8F48], [], [], [], [], [], []
Tue Apr 1 10:54:35 2008
Trace dumping is performing id=[cdmp_20080401105435]
Tue Apr 1 10:55:04 2008
Errors in file /oracle/admin/zhjs/bdump/zhjs2_pmon_10630.trc:
ORA-00481: LMON process terminated with error
Tue Apr 1 10:55:04 2008
PMON: terminating instance due to error 481
在宕机前出现的ORA-600错误和ORA-7445错误都可能是导致数据库宕机的原因。在上面的例子里，宕机前lmon出现了ORA-[kjrfr:!Owner],最终导致了pmon进程故障，导致宕机。Lmon进程的日志和pmon的日志是分析本次宕机的关键性的日志文件，需要认真的阅读。
这种情况下，做一个宕机前的事件列表对于分析宕机原因是十分有用的，就像老白在分析这个案例的时候一样，根据每个事件发生的时间序列，列出所有的事件列表，很可能能帮助你找到一些解决问题的脉络。在做这个事件序列的时候，要注意的是，多个节点的时间可能存在很细微的差别，我们首先要检查一下两个服务器的时间差异，最好能够精确到秒，甚至比秒更小的单位。因为我们在按照时间对这些事件进行排列的时候会发现，很多事件之间的时间差异也就是几十毫秒，这些事件先后顺序如果排错了，那么就可能影响到我们对故障的判断。
RAC故障分析是一个十分细致的工作，我们在分析日志的时候，一般来说都会到METALINK上去查找相关的资料，在比对METALINK上的资料的时候，一定要十分认真。METALINK上的某分资料可能和你目前发生的问题十分类似，不过并不一定就和你的案例完全吻合。甚至在某些极端情况下，堆栈都完全相同，但是两个案例还是不同的。所以在做这方面比对的时候不要似是而非。
比如我们在查找ORA-600的时候，一般来说在KNOWNLAGE BASE里输入ORA-600的错误号，就能够找到一些和该ORA-600错误相关的资料，其中一般会包括一份概述性的文档，比如：
Subject: ORA-600 [525]
Doc ID: Note:138888.1 Type: REFERENCE
Last Revision Date: 03-APR-2008 Status: PUBLISHED
Note: For additional ORA-600 related information please read Note 146580.1
PURPOSE:
This article discusses the internal error "ORA-600 [525]", what
it means and possible actions. The information here is only applicable
to the versions listed and is provided only for guidance.
ERROR:
ORA-600 [525] [a] [b] [c] [d] [e] [f]
VERSIONS:
versions 7.3 to 10.1
DESCRIPTION:
This error is raised when a latch request violates the ordering rules.
Each parent latch has a hard-coded level# (level number) inherited by
all its child latches.
Each child latch is assigned a child# (child number).
The latch level#'s and child#'s are used to ensure all processes which
acquire multiple latches, acquire them in the same strict order.
This will prevent deadlocks between processes.
This internal error is raised when a second latch request violates the
ordering rules.
ARGUMENTS:
Arg [a] Address of Child Latch being requested
Arg [b] Level of Latch (level#)
Arg [c] Name of requested Latch
Arg [d] Child number of requested Latch (child#)
Arg [e] Address of Latch currently owned
Arg [f] Name of Latch currently owned
FUNCTIONALITY:
Kernel Service layer Latching & Wait-post Implementation
IMPACT:
PROCESS FAILURE
NON CORRUPTIVE - No underlying data corruption.
SUGGESTIONS:
If the Known Issues section below does not help in terms of identifying
a solution, please submit the trace files and alert.log to Oracle
Support Services for further analysis.
Known Issues:
Bug# 5894422 See Note 5894422.8
OERI[525] / OERI[kglsim_rebalru2]
Fixed: 10.2.0.4, 11.1.0.7, 11.2
Bug# 5115857 See Note 5115857.8
RMAN backup ends with OERI[525]
Fixed:
Bug# 4202347 See Note 4202347.8
ASM may crash with OERI:525
Fixed: 10.1.0.5, 10.2.0.1
Bug# 3752329 See Note 3752329.8
OERI[525] on [kjct flow control latch] in RAC
Fixed: 9.2.0.7
Bug# 2742518 See Note 2742518.8
Accessing X$GLOBALCONTEXT may fail with OERI:525 / hangs the DB
Fixed: 9.2.0.4, 10.1.0.2
Bug# 2588590 See Note 2588590.8
OERI[525] possible while growing the cursor hash table
Fixed: 9.2.0.4, 10.1.0.2
这份文档里，DESCRIPTION部分描述了错误的原因，ARGUMENTS里介绍了参数的含义。这两个部分对于分析问题是十分重要的。不过在很多ORA-600的相关文档里，DESCRIPTION描述基本上是空白的，或者无法获得更多的信息。SUGESTIONS小结描述了对这个问题的处理方法，不过这个小节往往都类似
If the Known Issues section below does not help in terms of identifying
a solution, please submit the trace files and alert.log to Oracle
Support Services for further analysis.
的套话，并没有多少实际意义。真正对我们有帮助的是下面的BUG描述，不过并不是每个ORA-600都能找到对应的BUG，也许你的故障现场和这些BUG都完全不一致。在这种情况下，需要查看同时搜索到的其他文档。其中有些ORA-600错误有Summary of Bugs Containing XXX的文档，这类文档对于定位BUG十分有用，里面介绍了和某个ORA-600相关的BUG的情况以及解决方案。如果你无法从这类文档中获得有用的信息，就需要查看搜索出来的其他文档。如果在KNOWNLAGE BASE中无法获得所需要的信息，你可以把搜索范围定位在bug database重新搜索。通过bug database中的BUG报告去和你的问题进行比对。要注意的是BUG DATABASE中的报告并不一定对应了BUG，很多是通过对客户的Service Request进行整理后生成的，还有很多BUG报告并没有处理完成。老白解决上海这个问题就是从一份BUG报告中获得了信息，从而坚定了自己对问题的判断，最终解决了问题。
如果BUG DATABASE仍然找不到你的答案，我们可以尝试一下搜索技术论坛，不过在技术论坛上找到解决方案的可能性很小，而且技术论坛中的信息很多都是没有经过确认的，不一定正确，甚至有些ORACLE客服人员的回答中都可能存在错误，因此在查看技术论坛的信息的时候一定要十分谨慎。
METALINK是一个技术宝库，对于DBA处理故障时十分有帮助的，如何用好METALINK，快速的从METALINK查找到自己所需要的知识，对于DBA来说至关重要。对于METALINK上下载下来的知识如何进行分门别类的存储，也是十分关键的。老白在这些年的工作中，已经从METALINK上下载了5、6000份文档，这些文档如何存放，如何检索就十分重要。老白也经常为了寻找某份以前看过的文档翻箱倒柜找上半天，直到老白开始使用火狐上的scrapbook这个插件。Scrapbook具有按目录存储的功能，并且可以对管理的所有文件建立全文检索索引，这些功能大大提高了文档管理的水平，也使查找资料变得更加容易。
----------------------------------------------