Oracle CRS 启动问题诊断

oracle, 技术分享

 

#工程师培训#

#CRS#

从10g开始，Oracle使用自己的CRS管理RAC集群，到了11g、12c，voting disk，ocr，共享存储等等都由Oracle自己的集群软件管理（从11g开始，名称由CRS调整为GI——Grid Infrastructure）。

对外提供服务的数据库集群，依赖于底层GI。而GI要求共享存储、网络通讯、节点间进程通讯都准备就绪，才能正常运行。GI本就是由许多组件构成的集群（复杂）管理系统，雪上加霜的是，由于GI的日志输出中，有过多的Info级别的信息，且各个组件都有自己的日志，这些都造成了如果GI启动不成功，定位故障点比较困难。

本文结合MOS 《Troubleshoot Grid Infrastructure Startup Issues》一文对GI启动问题进行梳理。

首先还是来说日志，先要能确定其存储位置：

  1. Oracle 10g， 存储于$GRID HOME/log/name>/… ，当然在10g中其实还没有明确定义GRID HOME。
  2. Oracle 11g， $GRID HOME/log/name>/ , 好像跟10g的没有区别
  3. Oracle 12c，发生了改变，不加注意，容易在出问题时找不到日志

3.1 Standard cluster: $ORACLE_BASE/diag/crs/… 位置发生了改变，并且彻底使用ADR来管理日志。

3.2 Flex cluster： $ORACLE HOME/log/name> 

因为Grid Infrastructure组件较多（CRSD，CSSD，EVENTD…)，所以日志也就很多，总体来说，应该先查看alert.log ，再查看各组件的日志。

即使你已经对于去哪里能找到Grid Infrastructure的日志很清楚，真正面对目录中那么多日志、trace，以及日志中不知道什么意思的各种输出，很容易迷失。我的经验是，在“陷入”日志之前，先从操作系统角度查找一下，有没有什么明显的问题，导致Grid Infra不能启动。

OS级别的检查：

  1. 网络PING，将/etc/hosts中定义的，集群内的各个IP都ping一下
  2. 共享存储，以及其权限
  3. 文件系统空间使用、inode使用（Grid Infra经常因为产生日志太多，用尽inode，把自己撑死）
  4. … 总觉得还有别的，以后想到再补充

GI 启动顺序

操作系统启动ohasd —》 ohasd 启动 agents —》 启动守护进程（gipcd，mdnsd，pgnpd，ctssd，ocssd，crsd，evmd，asm等等），然后crsd启动agents —》 启动用户资源（数据库，SCAN，监听等等）。

检查集群状态

查看集群和守护进程状态

$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

$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的守护进程，比如ora.crsd离线了：

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

第一种情况，OHASD没有启动

ohasd.bin进程是整个集群的起源，因为正是ohasd.bin负责启动其他的集群进程，ohasd.bin不能正常启动的话，集群的其他部分就没有机会启动。如果ohasd.bin没有启动，之前的检查会返回CRS-4639（Could not contact Oracle High Availablity Services）错误；如果再ohasd.bin已经启动情况下，再次尝试启动它会触发CRS-4640错误；如果启动ohasd.bin失败，会返回如下错误：

CRS-4124: Oracle High Availability Services startup failed.

CRS-4000: Command Start failed, or completed with errors.

ohasd.binde正常启动，前提条件是：

  1. OS 在正确level运行（针对*nix操作系统）

cat /etc/inittab|grep init.ohasd

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

对于以SYSV方式管理自启动的，可以通过上述命令检查ohasd的启动配置；需要注意，RHEL6/OL6，不再使用inittab，改用upstart来管理自启动，配置会存储在/etc/init/oracle-ohasd.conf中，但是你仍然可以用/etc/init.d/init.ohasd run来启动它。对于RHEL7/OL7，systemd替代upstart进行自启动管理，配置应该存储在/etc/systemd/system/oracle-ohasd.service中。

上述检查显示，ohasd期望运行在level 3和level 5（不同的操作系统平台，期望的level不同）

检查当前运行的level：

who -r （这个命令是在任意操作系统平台都可以运行）

  1. init.ohasd run 进程应该已经启动

前文已经说及，在系统中不管是SYSV、UPSTART，还是SYSTEMD管理的服务自启动，操作系统都需要启动 init.ohasd run 进程（这个工作由init进程——PID为1的那个进程），而且如果这个进程失败，init进程还会负责重启（respawn）它，可通过ps命令检查init.ohasd run是否运行：

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

注意： init.ohasd不能启动可能是由于Snn 命令脚本stuck造成的（rcn.d文件夹中，会有多个Snn命令脚本，init进程会按照顺序启动这些脚本，可能在轮到ohasd之前，init进程就stuck住了）。

如果init.ohasd 没有在预期时间内启动，操作系统日志会有[ohasd()] CRS-0715： Oracle High Availability Service has timed out waiting for init.ohasd to be started.

临时的解决方案是手工启动init.ohasd

cd 

nohup ./init.ohasd run &

  1. 集群的自启动特性应该打开——默认是打开的

enable：

$GRID_HOME/bin/crsctl enable crs

确认：

$GRID_HOME/bin/crsctl config crs

另外，如果在操作系统日志中出现如下类似消息：

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

表示指定文件不存在或者不可访问了，这个有可能是被认为修改或者错误的opatch操作导致的

  1. syslogd 守护进程已经启动，OS能够执行初始化脚本S96ohasd

正常情况下，系统日志中应出现如下消息，表示ohasd启动：

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

有可能syslogd没有完全启动，Grid Infrastructure也会启动失败。为了诊断操作系统是否启动了S96ohasd，可以修改S96ohasd脚本，加入一些调试代码——比如 /bin/touch /tmp/ohasd.start.”date”。

如果确认S96ohasd是启动了的，但是在操作系统日志中却没有出现前文所述的 … is enabled for autostart 消息，表示可能是因为syslogd没有完全启动，替代解决方案是，sleep 120 等待2分钟，让syslogd先启动。

  1. 要求GRID_HOME所在文件系统要在线，S96ohasd执行后，操作系统日志中应出现如下消息：

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 crsconfigrac1_env.txt /ocw/grid/bin/ohasd.bin “reboot”

前一条消息，表示S96ohasd成功执行，后一条消息是执行GRID HOME下的脚本，如果看到了前面的消息，而没看到后一条消息，极有可能GRIDHOME文件系统没有online。

  1. 要求Oracle Local Registry（OLR，$GRID_HOME/cdata/*.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.

解决方法是，从备份恢复OLR，ocrconfig -local -restore backupname>”。

默认情况下，OLR备份可以在$GRID HOME/cdata/$HOST/backup$TIME_STAMP.olr 出找到。

  1. 要求ohasd.bin能够访问网络socket文件，如失败会出现类似如下日志：

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

2010-06-29 10:31:01.571: [ OCRSRV][1217390912]th_listen: CLSCLISTEN failedclsc ret= 3, addr= [(ADDRESS=(PROTOCOL=ipc)(KEY=procrlocal conn_0PROL))]

2010-06-29 10:31:01.571: [ OCRSRV][3267002960]th_init: Local listener did not reach valid state

  1. ohasd.bin进程要能够访问日志路径，如果日志有问题，操作系统日志中会出现类似如下消息：

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

  1. 节点重启后，SUSE Linux平台，可能出现ohasd启动失败，参见note 1325718.1，解决方案是启动raw服务（即使系统没有使用raw device）
  2. OHASD启动失败， ps -ef|grep ohasd.bin可以看到进程，但是在$GRID_HOME/log//ohasd/ohasd.log中长时间看不到输出，对进程进行truss，显示其一直在尝试关闭非法的文件handles：

..

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

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

..

对ohasd.bin进程用pstack检查，发现其在调用：

close sclssutlclosefiledescriptors main ..

这是bug 11834289，已经在11.2.0.3中解决。

  1.  ohasd.bin启动成功，但是 crsctl check crs 只显示如下一行：

CRS-4638: Oracle High Availability Services is online

执行crsctl stat res -p -init没有输出，这一般也是OLR损坏造成的，参照前文进行OLR恢复。

  1. OL7/RHEL7中，由于bug 18370031导致，需要为11.2.0.4版本安装patch 18370021（在执行root.sh之前）。这个主要是因为集群软件没有支持systemd引起的。
  2. OL7/RHEL7，需要补丁程序25606616 ，这个属于安装问题，应在安装时确认需要的补丁程序都已安装。

第二种情况，OHASD Agents没有启动

OHASD.BIN会产生4个agents程序，来启动其他资源：

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进程）。

任意agent程序没有启动成功，集群都会处于“非健康”状态。

  1. agent启动失败最常见的原因是日志文件或者日志文件夹没有设置合适的ownership或者权限
  2. agent可执行程序二进制文件损坏

第三种情况， OCSSD.BIN没有启动

  1. GPnP profile 需要能够被访问，如果访问失败，ocssd.log会出现类似下面的日志输出：

2010-02-03 22:26:17.057: [ GPnP][3852126240]clsgpnpm_connect: [at clsgpnpm.c:1100] GIPC gipcretConnectionRefused (29) gipcConnect(ipc-ipc://GPNPD_rac1)

2010-02-03 22:26:17.057: [ GPnP][3852126240]clsgpnpm connect: [at clsgpnpm.c:1101] Result: (48) CLSGPNPCOMM_ERR. Failed to connect to call url “ipc://GPNPD_rac1”

2010-02-03 22:26:17.057: [ GPnP][3852126240]clsgpnp getProfileEx: [at clsgpnp.c:546] Result: (13) CLSGPNPNO_DAEMON. Can’t get GPnP service profile from local GPnP daemon

2010-02-03 22:26:17.057: [ default][3852126240]Cannot get GPnP profile. Error CLSGPNP NODAEMON (GPNPD daemon is not running).

2010-02-03 22:26:17.057: [ CSSD][3852126240]clsgpnp_getProfile failed, rc(13)

  1. Voting Disk要能正常访问

在11.2中，ocssd.bin会根据GPnP profile的信息，来访问Voting disk，如果没有足够的voting disk被确认，ocssd.bin本身会退出：

2010-02-03 22:37:22.212: [ CSSD][2330355744]clssnmReadDiscoveryProfile: voting file discovery string(/share/storage/di*)

..

2010-02-03 22:37:22.227: [ CSSD][1145538880]clssnmvDiskVerify: Successful discovery of 0 disks

2010-02-03 22:37:22.227: [ CSSD][1145538880]clssnmCompleteInitVFDiscovery: Completing initial voting file discovery

2010-02-03 22:37:22.227: [ CSSD][1145538880]clssnmvFindInitialConfigs: No voting files found

2010-02-03 22:37:22.228: [ CSSD][1145538880]###################################

2010-02-03 22:37:22.228: [ CSSD][1145538880]clssscExit: CSSD signal 11 in thread clssnmvDDiscThread

另外，如果ocssd.bin在启动过程中，发现有voting 文件发生修改，会启动失败：

2010-05-02 03:11:19.033: [ CSSD][1197668093]clssnmCompleteInitVFDiscovery: Detected voting file add in progress for CIN 0:1134513465:0, waiting for configuration to complete 0:1134513098:0

这种情况下，需要以“独占”exclusive方式启动集群，参见note 1364971.1

如果voting disk没有使用ASM设备管理，其“属主”、权限应如下：

-rw-r—— 1 ogrid oinstall 21004288 Feb 4 09:13 votedisk1

  1. 网络、名称解析要运行正常，否则ocssd.bin会失败

网络没有准备好：

2010-02-03 23:26:25.804: [GIPCXCPT][1206540320]gipcmodGipcPassInitializeNetwork: failed to find any interfaces in clsinet, ret gipcretFail (1)

2010-02-03 23:26:25.804: [GIPCGMOD][1206540320]gipcmodGipcPassInitializeNetwork: EXCEPTION[ ret gipcretFail (1) ] failed to determine host from clsinet, using default

..

2010-02-03 23:26:25.810: [ CSSD][1206540320]clsssclsnrsetup: gipcEndpoint failed, rc 39

2010-02-03 23:26:25.811: [ CSSD][1206540320]clssnmOpenGIPCEndp: failed to listen on gipc addr gipc://rac1:nm_eotcs- ret 39

2010-02-03 23:26:25.811: [ CSSD][1206540320]clssscmain: failed to open gipc endp

private 网络连通性有问题（包括multicast没有开启）：

2010-09-20 11:52:54.014: [ CSSD][1103055168]clssnmvDHBValidateNCopy: node 1, racnode1, has a disk HB, but no network HB, DHB has rcfg 180441784, wrtcnt, 453, LATS 328297844, lastSeqNo 452, uniqueness 1284979488, timestamp 1284979973/329344894

2010-09-20 11:52:54.016: [ CSSD][1078421824]clssgmWaitOnEventValue: after CmInfo State val 3, eval 1 waited 0

.. >>>> after a long delay

2010-09-20 12:02:39.578: [ CSSD][1103055168]clssnmvDHBValidateNCopy: node 1, racnode1, has a disk HB, but no network HB, DHB has rcfg 180441784, wrtcnt, 1037, LATS 328883434, lastSeqNo 1036, uniqueness 1284979488, timestamp 1284980558/329930254

2010-09-20 12:02:39.895: [ CSSD][1107286336]clssgmExecuteClientRequest: MAINT recvd from proc 2 (0xe1ad870)

2010-09-20 12:02:39.895: [ CSSD][1107286336]clssgmShutDown: Received abortive shutdown request from client.

2010-09-20 12:02:39.895: [ CSSD][1107286336]###################################

2010-09-20 12:02:39.895: [ CSSD][1107286336]clssscExit: CSSD aborting from thread GMClientListener

2010-09-20 12:02:39.895: [ CSSD][1107286336]###################################

验证网络设置，参见 note 1054902.1

需要检查集群心跳网卡名称与gpnp profile所存储的一致（gpnptool get），在11.2.0.1中如果private网络不可用，ocssd.bin会使用public网络。

  1. Vendor clusterware要正常启动（我想说的是，尽量不要使用什么Vendor clusterware）

这个原因，导致ocssd.bin不能启动，其日志中会有类似如下输出：

2010-08-30 18:28:13.207: [ CSSD][36]clssnm_skgxninit: skgxncin failed, will retry

2010-08-30 18:28:14.207: [ CSSD][36]clssnm_skgxnmon: skgxn init failed

2010-08-30 18:28:14.208: [ CSSD][36]###################################

2010-08-30 18:28:14.208: [ CSSD][36]clssscExit: CSSD signal 11 in thread skgxnmon

  1. 使用错误位置的crsctl来启动

第四种情况， CRSD.BIN没有启动

如果，crsctl status res -t -init 显示ora.crsd的状态是intermidiate，并且这个节点不是第一个启动CRS的节点（集群中，有其他节点正运行着crsd），基本上都是这个节点的crsd无法和主节点上的crsd通信造成的。（这种情况下，手贱的可以去尝试kill master crsd进行解决）。

crsd.bin如果是MASTER，在其日志汇总会出现MASTER字样，被kill掉后，应该能够respawn，其他节点的crsd会成为MASTER。 

CRSD.BIN启动依赖于：

  1. ocssd.bin 完全启动

如ocssd.bin没有正常启动，crs的日志里会有类似如下输出：

2010-02-03 22:37:51.638: [ CSSCLNT][1548456880]clssscConnect: gipc request failed with 29 (0x16)

2010-02-03 22:37:51.638: [ CSSCLNT][1548456880]clsssInitNative: connect failed, rc 29

2010-02-03 22:37:51.639: [ CRSRTI][1548456880] CSS is not ready. Received status 3 from CSS. Waiting for good status ..

关键字： clssscConnect，clsssInitNative，CSS is not ready

  1. OCR能够正常访问

未完，但可能永远不会再补充……