11.2 RAC时间同步异常（一）

最新推荐文章于 2022-05-19 11:59:20 发布

ckawt40802

最新推荐文章于 2022-05-19 11:59:20 发布

阅读量428

点赞数

文章标签：数据库

一个客户的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 ID:
Session ID: 82 Serial number: 53
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 ID:
Session ID: 82 Serial number: 53
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 [4718636]
NOTE: force a map free for map id 2
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
[cssd(4391224)]CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc jzdbiufo .
2011-05-10 14:35:01.116
[cssd(4391224)]CRS-1632:Node jzdbiufo is being removed from the cluster in cluster incarnation 200459465
2011-05-10 14:35:01.144
[cssd(4391224)]CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc .
2011-05-10 14:35:03.192
[cssd(4391224)]CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc jzdbiufo .
2011-05-10 14:36:18.384
[cssd(4391224)]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
[cssd(4391224)]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
[cssd(4391224)]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
[cssd(4391224)]CRS-1632:Node jzdbiufo is being removed from the cluster in cluster incarnation 200459467
2011-05-10 14:36:33.312
[cssd(4391224)]CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc .
2011-05-10 14:54:16.181
[crsd(6422586)]CRS-2765:Resource 'ora.net1.network' has failed on server 'jzdbnc'.
2011-05-10 14:54:18.539
[/oracle/app/11.2.0/grid/bin/oraagent.bin(3014938)]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
[/oracle/app/11.2.0/grid/bin/oraagent.bin(3014938)]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
[crsd(6422586)]CRS-2765:Resource 'ora.net1.network' has failed on server 'jzdbnc'.
2011-05-10 14:56:15.055
[/oracle/app/11.2.0/grid/bin/oraagent.bin(3014938)]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
[/oracle/app/11.2.0/grid/bin/oraagent.bin(3014938)]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
[ctssd(5243264)]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
[ctssd(5243264)]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
[ctssd(5243264)]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
[ctssd(5243264)]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
[cssd(4259964)]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
[cssd(4259964)]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
[cssd(4259964)]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
[cssd(4259964)]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
[cssd(4259964)]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
[cssd(4259964)]CRS-1652:Starting clean up of CRSD resources.
2010-05-10 15:22:01.927
[cssd(4259964)]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
[/oracle/app/11.2.0/grid/bin/oraagent.bin(6946850)]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
[/oracle/app/11.2.0/grid/bin/oraagent.bin(6946850)]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
[cssd(4259964)]CRS-1654:Clean up of CRSD resources finished successfully.
2010-05-10 15:22:03.631
[cssd(4259964)]CRS-1655:CSSD on node jzdbiufo detected a problem and started to shutdown.
2010-05-10 15:22:03.722
[/oracle/app/11.2.0/grid/bin/oraagent.bin(7340044)]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
[/oracle/app/11.2.0/grid/bin/orarootagent.bin(6488506)]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
[/oracle/app/11.2.0/grid/bin/oraagent.bin(6946850)]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
[ohasd(4456806)]CRS-2765:Resource 'ora.crsd' has failed on server 'jzdbiufo'.
2010-05-10 15:22:05.042
[crsd(8978838)]CRS-0805:Cluster Ready Service aborted due to failure to communicate with Cluster Synchronization Service with error [3]. Details at (:CRSD00109:) in /oracle/app/11.2.0/grid/log/jzdbiufo/crsd/crsd.log.
2010-05-10 15:22:05.130
[ohasd(4456806)]CRS-2765:Resource 'ora.evmd' has failed on server 'jzdbiufo'.
2010-05-10 15:22:05.256
[/oracle/app/11.2.0/grid/bin/oraagent.bin(5243064)]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
[ohasd(4456806)]CRS-2765:Resource 'ora.ctssd' has failed on server 'jzdbiufo'.
2010-05-10 15:22:05.447
[ohasd(4456806)]CRS-2765:Resource 'ora.asm' has failed on server 'jzdbiufo'.
2010-05-10 15:22:05.512
[ohasd(4456806)]CRS-2765:Resource 'ora.crsd' has failed on server 'jzdbiufo'.
2010-05-10 15:22:06.490
[ohasd(4456806)]CRS-2765:Resource 'ora.diskmon' has failed on server 'jzdbiufo'.
2010-05-10 15:22:06.513
[ctssd(9765310)]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
[/oracle/app/11.2.0/grid/bin/oraagent.bin(5243064)]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
[ohasd(4456806)]CRS-2765:Resource 'ora.cluster_interconnect.haip' has failed on server 'jzdbiufo'.
2010-05-10 15:22:06.697
[/oracle/app/11.2.0/grid/bin/oraagent.bin(5243064)]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
[/oracle/app/11.2.0/grid/bin/oraagent.bin(5243064)]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
[/oracle/app/11.2.0/grid/bin/oraagent.bin(5243064)]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
[ohasd(4456806)]CRS-2765:Resource 'ora.cssd' has failed on server 'jzdbiufo'.
2010-05-10 15:22:07.210
[/oracle/app/11.2.0/grid/bin/oraagent.bin(5243064)]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
[/oracle/app/11.2.0/grid/bin/oraagent.bin(5243064)]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
[/oracle/app/11.2.0/grid/bin/oraagent.bin(5243064)]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
[cssd(6029520)]CRS-1713:CSSD daemon is started in clustered mode
2010-05-10 15:22:23.271
[cssd(6029520)]CRS-1707:Lease acquisition for node jzdbiufo number 2 completed
2010-05-10 15:22:24.721
[cssd(6029520)]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
[cssd(6029520)]CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc jzdbiufo .
2010-05-10 15:22:58.291
[cssd(6029520)]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
[cssd(6029520)]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
[cssd(6029520)]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
[/oracle/app/11.2.0/grid/bin/oraagent.bin(5243064)]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
[/oracle/app/11.2.0/grid/bin/oraagent.bin(5243064)]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
[cssd(7143634)]CRS-1713:CSSD daemon is started in clustered mode
2010-05-10 15:23:38.862
[ohasd(4456806)]CRS-2765:Resource 'ora.diskmon' has failed on server 'jzdbiufo'.
2010-05-10 15:23:42.191
[cssd(7143634)]CRS-1707:Lease acquisition for node jzdbiufo number 2 completed
2010-05-10 15:23:43.612
[cssd(7143634)]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
[cssd(7143634)]CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc jzdbiufo .
2010-05-10 15:24:47.942
[cssd(7143634)]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
[cssd(7143640)]CRS-1713:CSSD daemon is started in clustered mode
2010-05-10 15:24:56.013
[ohasd(4456806)]CRS-2765:Resource 'ora.diskmon' has failed on server 'jzdbiufo'.
2010-05-10 15:24:58.524
[cssd(7143640)]CRS-1707:Lease acquisition for node jzdbiufo number 2 completed
2010-05-10 15:24:59.942
[cssd(7143640)]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
[cssd(7143640)]CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc jzdbiufo .
2010-05-10 15:26:04.037
[cssd(7143640)]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
[cssd(9765338)]CRS-1713:CSSD daemon is started in clustered mode
2010-05-10 15:26:10.161
[ohasd(4456806)]CRS-2765:Resource 'ora.diskmon' has failed on server 'jzdbiufo'.
2010-05-10 15:26:14.713
[cssd(9765338)]CRS-1707:Lease acquisition for node jzdbiufo number 2 completed
2010-05-10 15:26:16.131
[cssd(9765338)]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
[cssd(9765338)]CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc jzdbiufo .
2010-05-10 15:27:21.247
[cssd(9765338)]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
[ohasd(4456806)]CRS-2765:Resource 'ora.diskmon' has failed on server 'jzdbiufo'.
2010-05-10 15:27:31.316
[cssd(11403498)]CRS-1713:CSSD daemon is started in clustered mode
2010-05-10 15:27:37.276
[cssd(11403498)]CRS-1707:Lease acquisition for node jzdbiufo number 2 completed
2010-05-10 15:27:38.714
[cssd(11403498)]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
[cssd(11403498)]CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc jzdbiufo .
2010-05-10 15:28:42.840
[cssd(11403498)]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
[cssd(6488556)]CRS-1713:CSSD daemon is started in clustered mode
2010-05-10 15:28:50.447
[ohasd(4456806)]CRS-2765:Resource 'ora.diskmon' has failed on server 'jzdbiufo'.
2010-05-10 15:28:53.652
[cssd(6488556)]CRS-1707:Lease acquisition for node jzdbiufo number 2 completed
2010-05-10 15:28:55.086
[cssd(6488556)]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
[cssd(6488556)]CRS-1601:CSSD Reconfiguration complete. Active nodes are jzdbnc jzdbiufo .
2010-05-10 15:29:59.214
[cssd(6488556)]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
[ohasd(4456806)]CRS-2765:Resource 'ora.diskmon' has failed on server 'jzdbiufo'.
2010-05-10 15:30:09.668
[ohasd(4456806)]CRS-2771:Maximum restart attempts reached for resource 'ora.cssd'; will not restart.