Oracle技术之11.2 RAC时间同步异常（一）
一个客户的11.2的RAC环境，出现了一个节点DOWN掉的问题。这个客户手工调整了系统的时间，使得两个节点的系统时间只相差几秒，而且还设置了11.2的自动时间同步功能。但是到了下午发现一个节点上的实例DOWN掉了，而且这时两个节点的时间相差了一个小时左右。
检查挂掉的节点上的数据库alert文件：
Mon May 10 15:22:03 2010
NOTE: ASMB terminating
Errors in file /oracle/app/oracle/diag/rdbms/posp/posp2/trace/posp2_asmb_8257792.trc:
ORA-15064: communication failure with ASM instance
ORA-03113: end-of-file on communication channel
Process>
Session> Errors in file /oracle/app/oracle/diag/rdbms/posp/posp2/trace/posp2_asmb_8257792.trc:
ORA-15064: communication failure with ASM instance
ORA-03113: end-of-file on communication channel
Process>
Session> ASMB (ospid: 8257792): terminating the instance due to error 15064
Instance terminated by ASMB, pid = 8257792
很显然导致问题的原因是连接不到ASM实例，这比如导致数据库实例的崩溃，再检查ASM实例的错误日志：
Mon May 10 15:00:13 2010
WARNING: Elapsed time did not advance (delta = 0),
WARNING: skipping disk repair timer updates for
WARNING: offline disks
Mon May 10 15:03:35 2010
WARNING: Elapsed time did not advance (delta = 0),
WARNING: skipping disk repair timer updates for
WARNING: offline disks
Mon May 10 15:06:56 2010
WARNING: Elapsed time did not advance (delta = 0),
WARNING: skipping disk repair timer updates for
WARNING: offline disks
Mon May 10 15:10:17 2010
WARNING: Elapsed time did not advance (delta = 0),
WARNING: skipping disk repair timer updates for
WARNING: offline disks
Mon May 10 15:13:39 2010
WARNING: Elapsed time did not advance (delta = 0),
WARNING: skipping disk repair timer updates for
WARNING: offline disks
Mon May 10 15:17:00 2010
WARNING: Elapsed time did not advance (delta = 0),
WARNING: skipping disk repair timer updates for
WARNING: offline disks
Mon May 10 15:20:21 2010
WARNING: Elapsed time did not advance (delta = 0),
WARNING: skipping disk repair timer updates for
WARNING: offline disks
Mon May 10 15:22:03 2010
NOTE: ASMB process exiting, either shutdown is in progress
NOTE: or foreground connected to ASMB was killed.
Mon May 10 15:22:03 2010
NOTE: client exited
NOTE: force a map free for map> Mon May 10 15:22:04 2010
PMON (ospid: 6816236): terminating the instance due to error 481
Instance terminated by PMON, pid = 6816236
ASM实例的被中止的原因是错误481，而Oracle对于这个错误的描述为：
ORA-00481: LMON process terminated with error
Cause: The global enqueue service monitor process died
Action: Warm start instance
看来问题和CLUSTER环境有关，而且ASM的告警日志中包含了大量的警告信息。
进一步检查CLUSTER上的相关信息：
2011-05-10 14:33:46.819
CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc jzdbiufo .
2011-05-10 14:35:01.116
CRS-1632:Node jzdbiufo is being removed from the cluster in cluster incarnation 200459465
2011-05-10 14:35:01.144
CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc .
2011-05-10 14:35:03.192
CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc jzdbiufo .
2011-05-10 14:36:18.384
CRS-1612:Network communication with node jzdbiufo (2) missing for 50% of timeout interval. Removal of this node from cluster in 14.896 seconds
2011-05-10 14:36:26.422
CRS-1611:Network communication with node jzdbiufo (2) missing for 75% of timeout interval. Removal of this node from cluster in 6.859 seconds
2011-05-10 14:36:30.452
CRS-1610:Network communication with node jzdbiufo (2) missing for 90% of timeout interval. Removal of this node from cluster in 2.829 seconds
2011-05-10 14:36:33.285
CRS-1632:Node jzdbiufo is being removed from the cluster in cluster incarnation 200459467
2011-05-10 14:36:33.312
CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc .
2011-05-10 14:54:16.181
CRS-2765:Resource 'ora.net1.network' has failed on server 'jzdbnc'.
2011-05-10 14:54:18.539
CRS-5016:Process "/oracle/app/11.2.0/grid/bin/lsnrctl" spawned by agent "/oracle/app/11.2.0/grid/bin/oraagent.bin" for action "check" failed: details at "(:CLSN00010:)" in "/oracle/app/11.2.0/grid/log/jzdbnc/agent/crsd/oraagent_grid/oraagent_grid.log"
2011-05-10 14:54:18.574
CRS-5016:Process "/oracle/app/11.2.0/grid/opmn/bin/onsctli" spawned by agent "/oracle/app/11.2.0/grid/bin/oraagent.bin" for action "check" failed: details at "(:CLSN00010:)" in "/oracle/app/11.2.0/grid/log/jzdbnc/agent/crsd/oraagent_grid/oraagent_grid.log"
2011-05-10 14:56:13.440
CRS-2765:Resource 'ora.net1.network' has failed on server 'jzdbnc'.
2011-05-10 14:56:15.055
CRS-5016:Process "/oracle/app/11.2.0/grid/opmn/bin/onsctli" spawned by agent "/oracle/app/11.2.0/grid/bin/oraagent.bin" for action "check" failed: details at "(:CLSN00010:)" in "/oracle/app/11.2.0/grid/log/jzdbnc/agent/crsd/oraagent_grid/oraagent_grid.log"
2011-05-10 14:56:16.179
CRS-5016:Process "/oracle/app/11.2.0/grid/bin/lsnrctl" spawned by agent "/oracle/app/11.2.0/grid/bin/oraagent.bin" for action "check" failed: details at "(:CLSN00010:)" in "/oracle/app/11.2.0/grid/log/jzdbnc/agent/crsd/oraagent_grid/oraagent_grid.log"
单从节点1的CLUSTER的trace信息看，似乎是网络的问题导致了另一个节点被关闭，检查节点2上的信息：
2010-05-10 14:38:20.599
CRS-2404:The Cluster Time Synchronization Service detects that the local time is significantly different from the mean cluster time. Details in /oracle/app/11.2.0/grid/log/jzdbiufo/ctssd/octssd.log.
2010-05-10 14:38:20.599
CRS-2408:The clock on host jzdbiufo has been updated by the Cluster Time Synchronization Service to be synchronous with the mean cluster time.
2010-05-10 15:11:25.818
CRS-2404:The Cluster Time Synchronization Service detects that the local time is significantly different from the mean cluster time. Details in /oracle/app/11.2.0/grid/log/jzdbiufo/ctssd/octssd.log.
2010-05-10 15:11:25.818
CRS-2408:The clock on host jzdbiufo has been updated by the Cluster Time Synchronization Service to be synchronous with the mean cluster time.
2010-05-10 15:21:46.319
CRS-1612:Network communication with node jzdbnc (1) missing for 50% of timeout interval. Removal of this node from cluster in 14.926 seconds
2010-05-10 15:21:54.322
CRS-1611:Network communication with node jzdbnc (1) missing for 75% of timeout interval. Removal of this node from cluster in 6.923 seconds
2010-05-10 15:21:58.348
CRS-1610:Network communication with node jzdbnc (1) missing for 90% of timeout interval. Removal of this node from cluster in 2.897 seconds
2010-05-10 15:22:01.253
CRS-1609:This node is unable to communicate with other nodes in the cluster and is going down to preserve cluster integrity; details at (:CSSNM00008:) in /oracle/app/11.2.0/grid/log/jzdbiufo/cssd/ocssd.log.
2010-05-10 15:22:01.254
CRS-1656:The CSS daemon is terminating due to a fatal error; Details at (:CSSSC00012:) in /oracle/app/11.2.0/grid/log/jzdbiufo/cssd/ocssd.log
2010-05-10 15:22:01.339
CRS-1652:Starting clean up of CRSD resources.
2010-05-10 15:22:01.927
CRS-1608:This node was evicted by node 1, jzdbnc; details at (:CSSNM00005:) in /oracle/app/11.2.0/grid/log/jzdbiufo/cssd/ocssd.log.
2010-05-10 15:22:03.111
CRS-5016:Process "/oracle/app/11.2.0/grid/opmn/bin/onsctli" spawned by agent "/oracle/app/11.2.0/grid/bin/oraagent.bin" for action "check" failed: details at "(:CLSN00010:)" in "/oracle/app/11.2.0/grid/log/jzdbiufo/agent/crsd/oraagent_grid/oraagent_grid.log"
2010-05-10 15:22:03.611
CRS-5016:Process "/oracle/app/11.2.0/grid/bin/lsnrctl" spawned by agent "/oracle/app/11.2.0/grid/bin/oraagent.bin" for action "check" failed: details at "(:CLSN00010:)" in "/oracle/app/11.2.0/grid/log/jzdbiufo/agent/crsd/oraagent_grid/oraagent_grid.log"
2010-05-10 15:22:03.618
CRS-1654:Clean up of CRSD resources finished successfully.
2010-05-10 15:22:03.631
CRS-1655:CSSD on node jzdbiufo detected a problem and started to shutdown.
2010-05-10 15:22:03.722
CRS-5822:Agent '/oracle/app/11.2.0/grid/bin/oraagent_oracle' disconnected from server. Details at (:CRSAGF00117:) {0:3:4} in /oracle/app/11.2.0/grid/log/jzdbiufo/agent/crsd/oraagent_oracle/oraagent_oracle.log.
2010-05-10 15:22:03.722
CRS-5822:Agent '/oracle/app/11.2.0/grid/bin/orarootagent_root' disconnected from server. Details at (:CRSAGF00117:) {0:1:681} in /oracle/app/11.2.0/grid/log/jzdbiufo/agent/crsd/orarootagent_root/orarootagent_root.log.
2010-05-10 15:22:03.720
CRS-5822:Agent '/oracle/app/11.2.0/grid/bin/oraagent_grid' disconnected from server. Details at (:CRSAGF00117:) {0:2:9} in /oracle/app/11.2.0/grid/log/jzdbiufo/agent/crsd/oraagent_grid/oraagent_grid.log.
2010-05-10 15:22:03.927
CRS-2765:Resource 'ora.crsd' has failed on server 'jzdbiufo'.
2010-05-10 15:22:05.042
CRS-0805:Cluster Ready Service aborted due to failure to communicate with Cluster Synchronization Service with error . Details at (:CRSD00109:) in /oracle/app/11.2.0/grid/log/jzdbiufo/crsd/crsd.log.
2010-05-10 15:22:05.130
CRS-2765:Resource 'ora.evmd' has failed on server 'jzdbiufo'.
2010-05-10 15:22:05.256
CRS-5011:Check of resource "+ASM" failed: details at "(:CLSN00006:)" in "/oracle/app/11.2.0/grid/log/jzdbiufo/agent/ohasd/oraagent_grid/oraagent_grid.log"
2010-05-10 15:22:05.431
CRS-2765:Resource 'ora.ctssd' has failed on server 'jzdbiufo'.
2010-05-10 15:22:05.447
CRS-2765:Resource 'ora.asm' has failed on server 'jzdbiufo'.
2010-05-10 15:22:05.512
CRS-2765:Resource 'ora.crsd' has failed on server 'jzdbiufo'.
2010-05-10 15:22:06.490
CRS-2765:Resource 'ora.diskmon' has failed on server 'jzdbiufo'.
2010-05-10 15:22:06.513
CRS-2402:The Cluster Time Synchronization Service aborted on host jzdbiufo. Details at (:ctss_css_init1:) in /oracle/app/11.2.0/grid/log/jzdbiufo/ctssd/octssd.log.
2010-05-10 15:22:06.520
CRS-5011:Check of resource "+ASM" failed: details at "(:CLSN00006:)" in "/oracle/app/11.2.0/grid/log/jzdbiufo/agent/ohasd/oraagent_grid/oraagent_grid.log"
2010-05-10 15:22:06.550
CRS-2765:Resource 'ora.cluster_interconnect.haip' has failed on server 'jzdbiufo'.
2010-05-10 15:22:06.697
CRS-5011:Check of resource "+ASM" failed: details at "(:CLSN00006:)" in "/oracle/app/11.2.0/grid/log/jzdbiufo/agent/ohasd/oraagent_grid/oraagent_grid.log"
2010-05-10 15:22:06.868
CRS-5011:Check of resource "+ASM" failed: details at "(:CLSN00006:)" in "/oracle/app/11.2.0/grid/log/jzdbiufo/agent/ohasd/oraagent_grid/oraagent_grid.log"
2010-05-10 15:22:07.038
CRS-5011:Check of resource "+ASM" failed: details at "(:CLSN00006:)" in "/oracle/app/11.2.0/grid/log/jzdbiufo/agent/ohasd/oraagent_grid/oraagent_grid.log"
2010-05-10 15:22:07.056
CRS-2765:Resource 'ora.cssd' has failed on server 'jzdbiufo'.
2010-05-10 15:22:07.210
CRS-5011:Check of resource "+ASM" failed: details at "(:CLSN00006:)" in "/oracle/app/11.2.0/grid/log/jzdbiufo/agent/ohasd/oraagent_grid/oraagent_grid.log"
2010-05-10 15:22:07.381
CRS-5011:Check of resource "+ASM" failed: details at "(:CLSN00006:)" in "/oracle/app/11.2.0/grid/log/jzdbiufo/agent/ohasd/oraagent_grid/oraagent_grid.log"
2010-05-10 15:22:07.551
CRS-5011:Check of resource "+ASM" failed: details at "(:CLSN00006:)" in "/oracle/app/11.2.0/grid/log/jzdbiufo/agent/ohasd/oraagent_grid/oraagent_grid.log"
2010-05-10 15:22:16.783
CRS-1713:CSSD daemon is started in clustered mode
2010-05-10 15:22:23.271
CRS-1707:Lease acquisition for node jzdbiufo number 2 completed
2010-05-10 15:22:24.721
CRS-1605:CSSD voting file is online: /dev/rhdisk2; details in /oracle/app/11.2.0/grid/log/jzdbiufo/cssd/ocssd.log.
2010-05-10 15:22:31.678
CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc jzdbiufo .
2010-05-10 15:22:58.291
CRS-1612:Network communication with node jzdbnc (1) missing for 50% of timeout interval. Removal of this node from cluster in 14.741 seconds
2010-05-10 15:23:06.292
CRS-1611:Network communication with node jzdbnc (1) missing for 75% of timeout interval. Removal of this node from cluster in 6.740 seconds
2010-05-10 15:23:31.691
CRS-1656:The CSS daemon is terminating due to a fatal error; Details at (:CSSSC00011:) in /oracle/app/11.2.0/grid/log/jzdbiufo/cssd/ocssd.log
2010-05-10 15:23:32.432
CRS-5011:Check of resource "+ASM" failed: details at "(:CLSN00006:)" in "/oracle/app/11.2.0/grid/log/jzdbiufo/agent/ohasd/oraagent_grid/oraagent_grid.log"
2010-05-10 15:23:32.904
CRS-5011:Check of resource "+ASM" failed: details at "(:CLSN00006:)" in "/oracle/app/11.2.0/grid/log/jzdbiufo/agent/ohasd/oraagent_grid/oraagent_grid.log"
2010-05-10 15:23:36.240
CRS-1713:CSSD daemon is started in clustered mode
2010-05-10 15:23:38.862
CRS-2765:Resource 'ora.diskmon' has failed on server 'jzdbiufo'.
2010-05-10 15:23:42.191
CRS-1707:Lease acquisition for node jzdbiufo number 2 completed
2010-05-10 15:23:43.612
CRS-1605:CSSD voting file is online: /dev/rhdisk2; details in /oracle/app/11.2.0/grid/log/jzdbiufo/cssd/ocssd.log.
2010-05-10 15:23:47.928
CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc jzdbiufo .
2010-05-10 15:24:47.942
CRS-1656:The CSS daemon is terminating due to a fatal error; Details at (:CSSSC00011:) in /oracle/app/11.2.0/grid/log/jzdbiufo/cssd/ocssd.log
2010-05-10 15:24:52.471
CRS-1713:CSSD daemon is started in clustered mode
2010-05-10 15:24:56.013
CRS-2765:Resource 'ora.diskmon' has failed on server 'jzdbiufo'.
2010-05-10 15:24:58.524
CRS-1707:Lease acquisition for node jzdbiufo number 2 completed
2010-05-10 15:24:59.942
CRS-1605:CSSD voting file is online: /dev/rhdisk2; details in /oracle/app/11.2.0/grid/log/jzdbiufo/cssd/ocssd.log.
2010-05-10 15:25:04.024
CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc jzdbiufo .
2010-05-10 15:26:04.037
CRS-1656:The CSS daemon is terminating due to a fatal error; Details at (:CSSSC00011:) in /oracle/app/11.2.0/grid/log/jzdbiufo/cssd/ocssd.log
2010-05-10 15:26:08.590
CRS-1713:CSSD daemon is started in clustered mode
2010-05-10 15:26:10.161
CRS-2765:Resource 'ora.diskmon' has failed on server 'jzdbiufo'.
2010-05-10 15:26:14.713
CRS-1707:Lease acquisition for node jzdbiufo number 2 completed
2010-05-10 15:26:16.131
CRS-1605:CSSD voting file is online: /dev/rhdisk2; details in /oracle/app/11.2.0/grid/log/jzdbiufo/cssd/ocssd.log.
2010-05-10 15:26:21.233
CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc jzdbiufo .
2010-05-10 15:27:21.247
CRS-1656:The CSS daemon is terminating due to a fatal error; Details at (:CSSSC00011:) in /oracle/app/11.2.0/grid/log/jzdbiufo/cssd/ocssd.log
2010-05-10 15:27:27.281
CRS-2765:Resource 'ora.diskmon' has failed on server 'jzdbiufo'.
2010-05-10 15:27:31.316
CRS-1713:CSSD daemon is started in clustered mode
2010-05-10 15:27:37.276
CRS-1707:Lease acquisition for node jzdbiufo number 2 completed
2010-05-10 15:27:38.714
CRS-1605:CSSD voting file is online: /dev/rhdisk2; details in /oracle/app/11.2.0/grid/log/jzdbiufo/cssd/ocssd.log.
2010-05-10 15:27:42.826
CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc jzdbiufo .
2010-05-10 15:28:42.840
CRS-1656:The CSS daemon is terminating due to a fatal error; Details at (:CSSSC00011:) in /oracle/app/11.2.0/grid/log/jzdbiufo/cssd/ocssd.log
2010-05-10 15:28:47.578
CRS-1713:CSSD daemon is started in clustered mode
2010-05-10 15:28:50.447
CRS-2765:Resource 'ora.diskmon' has failed on server 'jzdbiufo'.
2010-05-10 15:28:53.652
CRS-1707:Lease acquisition for node jzdbiufo number 2 completed
2010-05-10 15:28:55.086
CRS-1605:CSSD voting file is online: /dev/rhdisk2; details in /oracle/app/11.2.0/grid/log/jzdbiufo/cssd/ocssd.log.
2010-05-10 15:28:59.200
CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc jzdbiufo .
2010-05-10 15:29:59.214
CRS-1656:The CSS daemon is terminating due to a fatal error; Details at (:CSSSC00011:) in /oracle/app/11.2.0/grid/log/jzdbiufo/cssd/ocssd.log
2010-05-10 15:30:07.582
CRS-2765:Resource 'ora.diskmon' has failed on server 'jzdbiufo'.
2010-05-10 15:30:09.668
CRS-2771:Maximum restart attempts reached for resource 'ora.cssd'; will not restart.
错误信息比较多，但是仔细观察不难发现，Oracle一直在进行时间同步的相关操作。
随后出现了网络问题，导致节点2从CLUSTER中被踢出，当节点2上的CRS等进程尝试重启时，又由于CLUSTER的同步服务错误而异常中止。
看来导致问题的原因和11.2的时间同步有关。
oracle视频教程请关注:http://u.youku.com/user_video/id_UMzAzMjkxMjE2.html
页:
[1]