【Oracle】RAC11gR2 Grid启动顺序及启动故障诊断思路

从11gR2开始，Oracle RAC的架构有了比较大的变化，集群层面相交于之前的版本有了比较大的变动，原来的rac架构基本上属于cssd、crsd、evmd三大光秃秃的主干进程，日志数量较少，对于rac无法启动原因，采用最原始的方法逐一查看各个进程的日志也可找到无法启动

从11gR2开始，Oracle RAC的架构有了比较大的变化，集群层面相交于之前的版本有了比较大的变动，原来的rac架构基本上属于cssd、crsd、evmd三大光秃秃的主干进程，日志数量较少，对于rac无法启动原因，采用最原始的方法逐一查看各个进程的日志也可找到无法启动的原因。然而从11gR2之后，集群层发生了比较大的变动，以下是$GRID_HOME/log/rac1/下的目录情况：

[grid@rac1 rac1]$ ls

acfs     acfsrepl      acfssec  agent          client   crfmond  cssd   cvu      evmd   gnsd   mdnsd  racg

acfslog  acfsreplroot  admin    alertrac1.log  crflogd  crsd     ctssd  diskmon  gipcd  gpnpd  ohasd  srvm

可以看到在这个目录中的文件夹非常多，在rac无法启动的情况下，如果去所有日志下查看无法启动的原因无疑效率极低。所以我们需要一个比较明确的诊断思路。

 

OK，接下来进入正题，希望可以为大家的日常诊断提供帮助。

 

第一步，在诊断Grid无法启动的情况之前我们需要先了解11gR2中Grid的启动流程，下面这张图比较清晰的说明了现在Grid的启动顺序：

 

从图中我们可以看到，相比的原来Oracle 10g的集群架构，11gR2有了比较大的改动。具体的进程作用在这里不再赘述，不了解的可以自己去恶补一下，这里只说进程启动顺序相关的内容。在启动集群的过程中首先启动的是ohasd进程，在ohasd进程启动之后会启动4个agent：

1.cssd agent

以root用户权限启动，负责启动cssd进程。

2.orarootagent

以root用户权限启动，负责启动以下这些守护进程：crsd进程、ctssd进程、Diskmon进程、acfs进程。这些进程也都是以root用户权限启动。

3.oraagent

以grid用户权限启动，负责mdnsd进程、gipcd进程、gpnpd进程、evmd进程、asm进程（11gR2之后的asm在集群中被放置到了更底层，和之前版本区别较大）。

4.cssdmonitor。

以root用户权限启动，负责cssdmonitor进程的启动。

 

从图中我们可以看到之后又由crsd进程负责启动了两个agent：orarootagent和oraagent（最后的进程中我们可以看到两个oraagent进程，就是之前启动的那个加上这个），之后再由orarootagent和oraagent去负责启动之后的用户资源，进程启动到这里我认为grid底层启动完毕，之后再由orarootagent和oraagent启动的资源出现的问题不再本文的讨论范围内了。

 

第二步，我们已经对grid的进程启动顺序进行了梳理，之后对于grid无法启动的诊断也就变得简单。我们只要通过ps -ef|grep /oracle/app/grid/product/11.2.0（$GRID_HOME）就可以了解到grid已经启动到哪一步，哪些进程已经启动，哪些进程还未启动，卡在了哪个进程上，这样我们就能快速找到应该查看的日志。比如crsd进程没有启动，我们就可以通过查看$GRID_HOME/log/rac1/crsd目录下的crsd.log来进行查看，究竟在crsd进程启动过程中遭遇了哪些错误导致进程无法正常启动。

 举例：

[grid@rac1 crsd]$ ps -ef|grep /oracle

root     15235     1  0 14:12 ?        00:00:06 /oracle/app/grid/product/11.2.0/bin/ohasd.bin reboot

grid     15356     1  0 14:12 ?        00:00:00 /oracle/app/grid/product/11.2.0/bin/oraagent.bin

grid     15367     1  0 14:12 ?        00:00:00 /oracle/app/grid/product/11.2.0/bin/mdnsd.bin

grid     15378     1  0 14:12 ?        00:00:02 /oracle/app/grid/product/11.2.0/bin/gpnpd.bin

grid     15388     1  2 14:12 ?        00:00:19 /oracle/app/grid/product/11.2.0/bin/gipcd.bin

root     15390     1  0 14:12 ?        00:00:00 /oracle/app/grid/product/11.2.0/bin/orarootagent.bin

root     15403     1  0 14:12 ?        00:00:08 /oracle/app/grid/product/11.2.0/bin/osysmond.bin

root     15477     1  0 14:12 ?        00:00:02 /oracle/app/grid/product/11.2.0/bin/ologgerd -M -d /oracle/app/grid/product/11.2.0/crf/db/rac1

root     15637     1  0 14:22 ?        00:00:00 /oracle/app/grid/product/11.2.0/bin/cssdmonitor

root     15665     1  0 14:22 ?        00:00:00 /oracle/app/grid/product/11.2.0/bin/cssdagent

grid     15676     1  0 14:22 ?        00:00:00 /oracle/app/grid/product/11.2.0/bin/ocssd.bin

grid     15730 13826  0 14:27 pts/1    00:00:00 grep /oracle

从以上的输出我们就可以看到，此时grid无法启动的原因在于cssd进程无法启动，所以我们直接查看ocssd.log，查看无法启动的原因，在日志中找到以下内容：

2016-05-09 14:30:26.476: [    CSSD][1104030016]clssnmvDHBValidateNcopy: node 2, rac2, has a disk HB, but no network HB, DHB has rcfg 358258450, wrtcnt, 177436, LATS 10923264, lastSeqNo 177435, uniqueness 1462763679, timestamp 1462775426/10874194

可以看到是因为私网出现了问题，导出有disk HB，而没有network HB，修复私网问题后，集群可以正常启动。

 

第三步，附送一篇MOS文章：ID 1623340.1，里边罗列了grid各个进程无法启动的常见原因以及对应的日志：

1.1.1. 集群状态

查询集群和守护进程的状态:

$GRID_HOME/bin/crsctl check crs
CRS-4638: Oracle High Availability Services is online
CRS-4537: Cluster Ready Services is online
CRS-4529: Cluster Synchronization Services is online
CRS-4533: Event Manager is online

$GRID_HOME/bin/crsctl stat res -t -init
--------------------------------------------------------------------------------
NAME           TARGET  STATE        SERVER                   STATE_DETAILS
--------------------------------------------------------------------------------
Cluster Resources
--------------------------------------------------------------------------------
ora.asm
      1        ONLINE  ONLINE       rac1                  Started
ora.crsd
      1        ONLINE  ONLINE       rac1
ora.cssd
      1        ONLINE  ONLINE       rac1
ora.cssdmonitor
      1        ONLINE  ONLINE       rac1
ora.ctssd
      1        ONLINE  ONLINE       rac1                  OBSERVER
ora.diskmon
      1        ONLINE  ONLINE       rac1
ora.drivers.acfs
      1        ONLINE  ONLINE       rac1
ora.evmd
      1        ONLINE  ONLINE       rac1
ora.gipcd
      1        ONLINE  ONLINE       rac1
ora.gpnpd
      1        ONLINE  ONLINE       rac1
ora.mdnsd
      1        ONLINE  ONLINE       rac1

对于11.2.0.2 和以上的版本，会有以下两个额外的进程：

ora.cluster_interconnect.haip
      1        ONLINE  ONLINE       rac1
ora.crf
      1        ONLINE  ONLINE       rac1

对于11.2.0.3 以上的非EXADATA的系统，ora.diskmon会处于offline的状态，如下：

ora.diskmon
      1        OFFLINE  OFFLINE       rac1

对于 12c 以上的版本, 会出现ora.storage资源：

ora.storage
1 ONLINE ONLINE racnode1 STABLE

如果守护进程 offline 我们可以通过以下命令启动:

$GRID_HOME/bin/crsctl start res ora.crsd -init

 

1.1.2. 问题 1: OHASD 无法启动

由于 ohasd.bin 的责任是直接或者间接的启动集群所有的其它进程，所以只有这个进程正常启动了，其它的进程才能起来，如果 ohasd.bin 的进程没有起来，当我们检查资源状态的时候会报错 CRS-4639 (Could not contact Oracle High Availability Services); 如果 ohasd.bin 已经启动了，而再次尝试启时，错误 CRS-4640 会出现；如果它启动失败了，那么我们会看到以下的错误信息：

CRS-4124: Oracle High Availability Services startup failed.
CRS-4000: Command Start failed, or completed with errors.

自动启动 ohasd.bin 依赖于以下的配置：

1. 操作系统配置了正确的 run level:

OS 需要在 CRS 启动之前设置成指定的 run level 来确保 CRS 的正常启动。

我们可以通过以下方式找到 CRS 需要 OS 设置的 run level：

cat /etc/inittab|grep init.ohasd
h1:35:respawn:/etc/init.d/init.ohasd run >/dev/null 2>&1 /null

以上例子展示了，CRS 需要 OS 运行在 run level 3 或 5；请注意，由于操作系统的不同，CRS 启动需要的 OS 的 run level 也会不同。

找到当前 OS 正在运行的 run level:

who -r

2. "init.ohasd run" 启动

在 Linux/Unix 平台上，由于"init.ohasd run" 是配置在 /etc/inittab中，进程 init（进程id 1，linux，Solars和HP-UX上为/sbin/init ，Aix上为/usr/sbin/init）会启动并且产生"init.ohasd run"进程，如果这个过程失败了，就不会有"init.ohasd run"的启动和运行，ohasd.bin 也是无法启动的：

ps -ef|grep init.ohasd|grep -v grep
root      2279     1  0 18:14 ?        00:00:00 /bin/sh /etc/init.d/init.ohasd run

注意：Oracle Linux (OL6)以及 Red Hat Linux 6 (RHEL6) 已经不再支持 inittab 了，所以 init.ohasd 会被配置在 /etc/init 中，并被 /etc/init 启动，尽管如此，我们还是应该能看到进程 "/etc/init.d/init.ohasd run" 被启动；

如果任何 rc Snncommand 的脚本（在 rcn.d 中，如 S98gcstartup）在启动的过程中挂死，此时 init 的进程可能无法启动"/etc/init.d/init.ohasd run"；您需要寻求 OS 厂商的帮助，找到为什么 Snncommand 脚本挂死或者无法正常启动的原因；

错误"[ohasd()] CRS-0715:Oracle High Availability Service has timed out waiting for init.ohasd to be started." 可能会在 init.ohasd 无法在指定时间内启动后出现
 
如果系统管理员无法在短期内找到 init.ohasd 无法启动的原因，以下办法可以作为一个临时的解决办法：

 cd
 nohup ./init.ohasd run &

3. Clusterware 自动启动；--自动启动默认是开启的

默认情况下 CRS 自动启动是开启的，我们可以通过以下方式开启：

$GRID_HOME/bin/crsctl enable crs

检查这个功能是否被开启:

$GRID_HOME/bin/crsctl config crs

如果以下信息被输出在OS的日志中

Feb 29 16:20:36 racnode1 logger: Oracle Cluster Ready Services startup disabled.
Feb 29 16:20:36 racnode1 logger: Could not access /var/opt/oracle/scls_scr/racnode1/root/ohasdstr

原因是由于这个文件不存在或者不可访问，产生这个问题的原因一般是人为的修改或者是打 GI 补丁的过程中使用了错误的 opatch (如：使用 Solaris 平台上的 opatch 在 Linux 上打补丁)


4. syslogd 启动并且 OS 能够执行 init 脚本 S96ohasd

节点启动之后，OS 可能停滞在一些其它的 Snn 的脚本上，所以可能没有机会执行到脚本 S96ohasd；如果是这种情况，我们不会在 OS 日志中看到以下信息

（aix /var/adm/syslog    linux /var/log/messages）

Jan 20 20:46:51 rac1 logger: Oracle HA daemon is enabled for autostart.

如果在 OS 日志里看不到上面的信息，还有一种可能是 syslogd（(/usr/sbin/syslogd）没有被完全启动。GRID 在这种情况下也是无法正常启动的，这种情况不适用于 AIX 的平台。

为了了解 OS 启动之后是否能够执行 S96ohasd 脚本，可以按照以下的方法修改该脚本：

From:

    case `$CAT $AUTOSTARTFILE` in
      enable*)
        $LOGERR "Oracle HA daemon is enabled for autostart."

To:

    case `$CAT $AUTOSTARTFILE` in
      enable*)
        /bin/touch /tmp/ohasd.start."`date`"
        $LOGERR "Oracle HA daemon is enabled for autostart."

重启节点后，如果您没有看到文件 /tmp/ohasd.start.timestamp 被创建，那么就是说 OS 停滞在其它的 Snn 的脚本上。如果您能看到 /tmp/ohasd.start.timestamp 生成了，但是"Oracle HA daemon is enabled for autostart"没有写入到messages 文件里，就是 syslogd 没有被完全启动了。以上的两种情况，您都需要寻求系统管理员的帮助，从 OS 的层面找到问题的原因，对于后一种情况，有个临时的解决办法是“休眠”2分钟， 按照以下的方法修改 ohasd 脚本：

From:

    case `$CAT $AUTOSTARTFILE` in
      enable*)
        $LOGERR "Oracle HA daemon is enabled for autostart."

To:

    case `$CAT $AUTOSTARTFILE` in
      enable*)
        /bin/sleep 120
        $LOGERR "Oracle HA daemon is enabled for autostart."

5. GRID_HOME 所在的文件系统在执行初始化脚本 S96ohasd 的时候在线；正常情况下一旦 S96ohasd 执行结束，我们会在 OS message 里看到以下信息：

Jan 20 20:46:51 rac1 logger: Oracle HA daemon is enabled for autostart.
..
Jan 20 20:46:57 rac1 logger: exec /ocw/grid/perl/bin/perl -I/ocw/grid/perl/lib /ocw/grid/bin/crswrapexece.pl /ocw/grid/crs/install/s_crsconfig_rac1_env.txt /ocw/grid/bin/ohasd.bin "reboot"

如果您只看到了第一行，没有看到最后一行的信息，很可能是 GRID_HOME 所在的文件系统在脚本 S96ohasd 执行的时候还没有正常挂载。


6. Oracle Local Registry  (OLR, $GRID_HOME/cdata/${HOSTNAME}.olr) 有效并可以正常读写

ls -l $GRID_HOME/cdata/*.olr
-rw------- 1 root  oinstall 272756736 Feb  2 18:20 rac1.olr

如果 OLR 是不可读写的或者损坏的，我们会在 ohasd.log 中看到以下的相关信息

..
2010-01-24 22:59:10.470: [ default][1373676464] Initializing OLR
2010-01-24 22:59:10.472: [  OCROSD][1373676464]utopen:6m':failed in stat OCR file/disk /ocw/grid/cdata/rac1.olr, errno=2, os err string=No such file or directory
2010-01-24 22:59:10.472: [  OCROSD][1373676464]utopen:7:failed to open any OCR file/disk, errno=2, os err string=No such file or directory
2010-01-24 22:59:10.473: [  OCRRAW][1373676464]proprinit: Could not open raw device
2010-01-24 22:59:10.473: [  OCRAPI][1373676464]a_init:16!: Backend init unsuccessful : [26]
2010-01-24 22:59:10.473: [  CRSOCR][1373676464] OCR context init failure.  Error: PROCL-26: Error while accessing the physical storage Operating System error [No such file or directory] [2]
2010-01-24 22:59:10.473: [ default][1373676464] OLR initalization failured, rc=26
2010-01-24 22:59:10.474: [ default][1373676464]Created alert : (:OHAS00106:) :  Failed to initialize Oracle Local Registry
2010-01-24 22:59:10.474: [ default][1373676464][PANIC] OHASD exiting; Could not init OLR

或者

..
2010-01-24 23:01:46.275: [  OCROSD][1228334000]utread:3: Problem reading buffer 1907f000 buflen 4096 retval 0 phy_offset 102400 retry 5
2010-01-24 23:01:46.275: [  OCRRAW][1228334000]propriogid:1_1: Failed to read the whole bootblock. Assumes invalid format.
2010-01-24 23:01:46.275: [  OCRRAW][1228334000]proprioini: all disks are not OCR/OLR formatted
2010-01-24 23:01:46.275: [  OCRRAW][1228334000]proprinit: Could not open raw device
2010-01-24 23:01:46.275: [  OCRAPI][1228334000]a_init:16!: Backend init unsuccessful : [26]
2010-01-24 23:01:46.276: [  CRSOCR][1228334000] OCR context init failure.  Error: PROCL-26: Error while accessing the physical storage
2010-01-24 23:01:46.276: [ default][1228334000] OLR initalization failured, rc=26
2010-01-24 23:01:46.276: [ default][1228334000]Created alert : (:OHAS00106:) :  Failed to initialize Oracle Local Registry
2010-01-24 23:01:46.277: [ default][1228334000][PANIC] OHASD exiting; Could not init OLR

或者

..
2010-11-07 03:00:08.932: [ default][1] Created alert : (:OHAS00102:) : OHASD is not running as privileged user
2010-11-07 03:00:08.932: [ default][1][PANIC] OHASD exiting: must be run as privileged user

或者

ohasd.bin comes up but output of "crsctl stat res -t -init"shows no resource, and "ocrconfig -local -manualbackup" fails

或者

..
2010-08-04 13:13:11.102: [   CRSPE][35] Resources parsed
2010-08-04 13:13:11.103: [   CRSPE][35] Server [] has been registered with the PE data model
2010-08-04 13:13:11.103: [   CRSPE][35] STARTUPCMD_REQ = false:
2010-08-04 13:13:11.103: [   CRSPE][35] Server [] has changed state from [Invalid/unitialized] to [VISIBLE]
2010-08-04 13:13:11.103: [  CRSOCR][31] Multi Write Batch processing...
2010-08-04 13:13:11.103: [ default][35] Dump State Starting ...
..
2010-08-04 13:13:11.112: [   CRSPE][35] SERVERS:
:VISIBLE:address{{Absolute|Node:0|Process:-1|Type:1}}; recovered state:VISIBLE. Assigned to no pool

------------- SERVER POOLS:
Free [min:0][max:-1][importance:0] NO SERVERS ASSIGNED

2010-08-04 13:13:11.113: [   CRSPE][35] Dumping ICE contents...:ICE operation count: 0
2010-08-04 13:13:11.113: [ default][35] Dump State Done.

解决办法就是使用下面的命令，恢复一个好的备份 "ocrconfig -local -restore "。

默认情况下，OLR 在系统安装结束后会自动的备份在 $GRID_HOME/cdata/$HOST/backup_$TIME_STAMP.olr 。

7. ohasd.bin可以正常的访问到网络的 socket 文件:

2010-06-29 10:31:01.570: [ COMMCRS][1206901056]clsclisten: Permission denied for (ADDRESS=(PROTOCOL=ipc)(KEY=procr_local_conn_0_PROL))

2010-06-29 10:31:01.571: [  OCRSRV][1217390912]th_listen: CLSCLISTEN failed clsc_ret= 3, addr= [(ADDRESS=(PROTOCOL=ipc)(KEY=procr_local_conn_0_PROL))]
2010-06-29 10:31:01.571: [  OCRSRV][3267002960]th_init: Local listener did not reach valid state

在 Grid Infrastructure 环境中，和 ohasd 有关的 socket 文件属主应该是 root 用户，但是在 Oracle Restart 的环境中，他们应该是属于 grid 用户的，关于更多的关于网络 socket 文件权限和属主，请参考章节"网络 socket 文件，属主和权限" 给出的例子.

8. ohasd.bin 能够访问日志文件的位置:

OS messages/syslog 显示以下信息:

Feb 20 10:47:08 racnode1 OHASD[9566]: OHASD exiting; Directory /ocw/grid/log/racnode1/ohasd not found.

请参考章节"日志位置, 属主和权限"部分的例子，并确定这些必要的目录是否有丢失的，并且是按照正确的权限和属主创建的。

9. 节点启动后，在 SUSE Linux 的系统上，ohasd 可能无法启动，此问题请参考 note 1325718.1 - OHASD not Starting After Reboot on SLES

10. OHASD 无法启动，使用 "ps -ef| grep ohasd.bin" 显示 ohasd.bin 的进程已经启动，但是 $GRID_HOME/log//ohasd/ohasd.log 在好几分钟之后都没有任何信息更新,使用 OS 的 truss 工具 可以看到该进程一致在循环的执行关闭从未被打开的文件句柄的操作:

..
15058/1:         0.1995 close(2147483646)                               Err#9 EBADF
15058/1:         0.1996 close(2147483645)                               Err#9 EBADF
..

通过 ohasd.bin 的 Call stack ，可以看到以下信息:

_close  sclssutl_closefiledescriptors  main ..

这是由于 bug 11834289 导致的， 该问题在 11.2.0.3 和之上的版本已经被修复,该 bug 的其它症状还有：集群的进程无法启动，而且做 call stack 和 truss 查看的时候也会看到相同的情况(循环的执行 OS 函数 "close") . 如果该 bug 发生在启动其它的资源时，我们会看到错误信息： "CRS-5802: Unable to start the agent process" 提示。

11. 其它的一些潜在的原因和解决办法请参见 note 1069182.1 - OHASD Failed to Start: Inappropriate ioctl for device

12. ohasd.bin 正常启动，但是, "crsctl check crs" 只显示以下一行信息:

CRS-4638: Oracle High Availability Services is online

并且命令 "crsctl stat res -p -init" 无法显示任何信息

这个问题是由于 OLR 损坏导致的，请参考 note 1193643.1 进行恢复。

 

13. 如果 ohasd 仍然无法启动，请参见 ohasd 的日志 /log//ohasd/ohasd.log 和 ohasdOUT.log 来获取更多的信息；
 

1.1.3. 问题 2: OHASD Agents  未启动

OHASD.BIN 会启动 4 个 agents/monitors 来启动其它的资源:

  oraagent: 负责启动  ora.asm, ora.evmd, ora.gipcd, ora.gpnpd, ora.mdnsd 等
  orarootagent: 负责启动 ora.crsd, ora.ctssd, ora.diskmon, ora.drivers.acfs 等
  cssdagent / cssdmonitor: 负责启动 ora.cssd(对应 ocssd.bin) 和 ora.cssdmonitor(对应 cssdmonitor)

如果 ohasd.bin 不能正常地启动以上任何一个 agents，集群都无法运行在正常的状态。

1. 通常情况下，agents 无法启动的原因是 agent 的日志或者日志所在的目录没有正确设置属主和权限。

关于日志文件和文件夹的权限和属主设置，请参见章节 "日志文件位置, 属主和权限" 中的介绍。

2. 如果 agent 的二进制文件（oraagent.bin 或者 orarootagent.bin 等）损坏, agent 也将无法启动，从而导致相关的资源也无法启动：

2011-05-03 11:11:13.189
[ohasd(25303)]CRS-5828:Could not start agent '/ocw/grid/bin/orarootagent_grid'. Details at (:CRSAGF00130:) {0:0:2} in /ocw/grid/log/racnode1/ohasd/ohasd.log.


2011-05-03 12:03:17.491: [    AGFW][1117866336] {0:0:184} Created alert : (:CRSAGF00130:) :  Failed to start the agent /ocw/grid/bin/orarootagent_grid
2011-05-03 12:03:17.491: [    AGFW][1117866336] {0:0:184} Agfw Proxy Server sending the last reply to PE for message:RESOURCE_START[ora.diskmon 1 1] ID 4098:403
2011-05-03 12:03:17.491: [    AGFW][1117866336] {0:0:184} Can not stop the agent: /ocw/grid/bin/orarootagent_grid because pid is not initialized
..
2011-05-03 12:03:17.492: [   CRSPE][1128372576] {0:0:184} Fatal Error from AGFW Proxy: Unable to start the agent process
2011-05-03 12:03:17.492: [   CRSPE][1128372576] {0:0:184} CRS-2674: Start of 'ora.diskmon' on 'racnode1' failed

..

2011-06-27 22:34:57.805: [    AGFW][1131669824] {0:0:2} Created alert : (:CRSAGF00123:) :  Failed to start the agent process: /ocw/grid/bin/cssdagent Category: -1 Operation: fail Loc: canexec2 OS error: 0 Other : no exe permission, file [/ocw/grid/bin/cssdagent]
2011-06-27 22:34:57.805: [    AGFW][1131669824] {0:0:2} Created alert : (:CRSAGF00126:) :  Agent start failed
..
2011-06-27 22:34:57.806: [    AGFW][1131669824] {0:0:2} Created alert : (:CRSAGF00123:) :  Failed to start the agent process: /ocw/grid/bin/cssdmonitor Category: -1 Operation: fail Loc: canexec2 OS error: 0 Other : no exe permission, file [/ocw/grid/bin/cssdmonitor]

解决办法： 您可以和正常节点上的 agent 文件进行比较，并且恢复一个好的副本回来。

1.1.4. 问题 3: OCSSD.BIN 无法启动