对应的超时时间为 900 秒，符合 CKPT 的超时定义，因此引起了我们的注意。关于 CKPT 方面的资料， 我们介绍如下：
■ CKPT 进程每 3 秒更新一次控制文件，这个操作我们可以成为“心跳”。CKPT 进程将为每一个实例 写唯一的一个数据块在控制文件头部， 通过这个信息维护心跳，成为“检查点进程记录”。当然在单
节点数据库也存在此信息。LMON 给每个 LMON 进程发送控制与状态信息。
在数据库内部，这些信息的接收具有 TIMEOUT 超时设定。如果信息发送失败或者出现接收到空信息，那 么 reconfiguration 动作将被触发。
■ LMON 在数据库通过内部参数 _cgs_send_timeout 定义超时，缺省为 300 秒。
■ CKPT 在数据库通过参数“ _controlfile_enqueue_timeout”定义超时，缺省为 900 秒。
本次的 LMON 进程日志 显示， CGS 超 时 条 件被触发 是本 次问题发 生的 触发条件 ， U1 的 日 志 u1_lmon_9208.trc 部分见下：
Begin DRM(41)
*** 2008-03-28 04:36:52.893 <<- - CLOCKTIME BEGIN
sent syncr inc 4 lvl 1097 to 0 (4,0/31/0) sent synca inc 4 lvl 1097 (4,0/31/0) sent syncr inc 4 lvl 1098 to 0 (4,0/34/0) sent synca inc 4 lvl 1098 (4,0/34/0) sent syncr inc 4 lvl 1099 to 0 (4,0/36/0) sent synca inc 4 lvl 1099 (4,0/36/0)
… …
sent synca inc 4 lvl 1104 (4,0/38/0)
*** 2008-03-28 04:51:54.355 <<- - 300S TIMEOUT TRIGGED kjfcdrmrfg: SYNC TIMEOUT (610433, 609532, 900), step 31
… …
而在 DIAG 进程的日志中可以发现，LMON 当时在访问控制文件，如下信息：
OSD pid info: Unix process pid: 9208, image: oracle@cupd25k-c (LMON) Dump of memory from 0x0000000402541A38 to 0x0000000402541C40
… …
Repeat 23 times
(FOB) flags=2 fib=5949008e0 incno=0 pending i/o cnt=0 fname=/dev/vx/rdsk/oradgUC/lv_uc_ctl3
fno=2 lblksz=4 fsiz=98499024
(FOB) flags=2 fib=594900540 incno=0 pending i/o cnt=0 fname=/dev/vx/rdsk/oradgUC/lv_uc_ctl2
fno=1 lblksz=4 fsiz=98499024
(FOB) flags=2 fib=5949001a0 incno=0 pending i/o cnt=0 fname=/dev/vx/rdsk/oradgUC/lv_uc_ctl1
fno=0 lblksz=4 fsiz=98499024
OSD pid info: Unix process pid: 9208, image: oracle@cupd25k-c (LMON) Dump of memory from 0x0000000402541A38 to 0x0000000402541C40
… …
Repeat 23 times
(FOB) flags=2 fib=5949008e0 incno=0 pending i/o cnt=0 fname=/dev/vx/rdsk/oradgUC/lv_uc_ctl3
fno=2 lblksz=4 fsiz=98499024
(FOB) flags=2 fib=594900540 incno=0 pending i/o cnt=0 fname=/dev/vx/rdsk/oradgUC/lv_uc_ctl2
fno=1 lblksz=4 fsiz=98499024
(FOB) flags=2 fib=5949001a0 incno=0 pending i/o cnt=0 fname=/dev/vx/rdsk/oradgUC/lv_uc_ctl1
fno=0 lblksz=4 fsiz=98499024
kjfsprn: dmap ver 4 (step 0)
DEFER MSG QUEUE ON LMD0 IS EMPTY SEQUENCES:
0:0.0 1:870037.0
DEFER MSG QUEUE ON LMS0 IS EMPTY SEQUENCES:
… …
DEFER MSG QUEUE ON LMS5 IS EMPTY SEQUENCES:
0:0.0 1:3464186.0
而此错误在高负载和锁请求频繁时发生，可以认为本次错误与网络拥塞无关。 可能性分析四：ORACLE 代码处理异常（BUG）
我们在分析最终认为，此种情况的可能性为 90%，不排除有其它原因（如 I/O HANG）导致 ORACLE 数据库对应的代码出错。不管起因如何，ORACLE 在 10.2.0.2 版本上，在本次事件的异常情况下处理， 在代码上存在缺陷。
理由一：DRM 检查未完成
DRM（dynamic resource mastering）功能在 ORACLE9.2 版本上存在但未被激活，因此只有 10G 版本存在此错误。几乎可以肯定的是，DRM 的轮询功能未能正常完成，应该是 ORACLE 本身对异常的处 理发生错误。
理由二：KJCDRMCFG 函数出现报错导致 LMON 异常
ORACLE 10.2.0.1~10.2.0.3 在 KJCDRMCFG 上面有很多 BUG，在高版本 10.2.0.4 上大部分已
经修复。此函数主要功能等待接收动态资源 REMASTER 信息。
三、结论、解决方案与建议
根据本次分析，我们得到的结论是：因为后台磁盘 I/O 挂起或其它异常原因，导致数据库在应用请求 不是在高负载情况下出现了异常，导致 DRM 过程中 CGS 超时条件被触发。
而此种超时，是由于 DRM 部分的处理代码，未能正确处理这部分异常造成，属于 ORACLE 软件的 BUG 类别。
修复建议：DRM 功能关闭或进行软件升级
此错误由 DRM 功能引起，因此可以选择将 DRM 功能关闭，将不再出现此错误。使用如下内部参数 关闭 DRM 功能：
1. _gc_integrity_checks = false
2. _gc_affinity_time=0
（DRM 在 ORACLE 10GR2 上生效）
3.2.1 关于DRM作用 DRM 在 10gr2 上被打开。每一个数据块在 RAC 下面均有一个主节点具有控制权。此节点将拥有此数
据块的锁资源。其它节点对此数据块的请求将进入请求队列。而决定数据块在那个节点上具有控制权及切 换，将有 DRM 轮询负责完成。DRM 将使 remaster 变快，提升了 RAC 的性能。
关闭 DRM 将导致 reconfiguration 动作比正常动作慢。同时，关闭 DRM 将因为数据块的 remaster 功能的关闭，损失部分数据库性能（大约 2～5%）。但关闭 DRM 功能不会有其它的负面作用。
2010年10月27日
Oracle DRM kjfcdrmrfg 超时错误分析一例
M
mac
Author
11 min
Read Time
7
Views
实例节点的警告日志，错误如下：
Fri Mar 28 04:52:24 2008
Errors in file /oracle/oracle/admin/UC/bdump/u1_lmon_9208.trc:
ORA-00481: LMON process terminated with error
Fri Mar 28 04:52:24 2008
LMON: terminating instance due to error 481
Fri Mar 28 04:52:24 2008
System state dump is made for local instance
System State dumped to trace file /oracle/oracle/admin/UC/bdump/u1_diag_9204.trc Fri Mar 28 04:52:28 2008
Instance terminated by LMON, pid = 9208
Fri Mar 28 04:57:08 2008
Starting ORACLE instance (normal)
… …
2 实例节点的警告日志片段如下：
Fri Mar 28 04:52:24 2008
Trace dumping is performing id=[cdmp_20080328045224] Fri Mar 28 04:52:32 2008
Reconfiguration started (old inc 4, new inc 6)
List of nodes: 1
Fri Mar 28 04:57:21 2008
Reconfiguration started (old inc 4, new inc 8)
List of nodes: 0 1
Nested reconfiguration detected. Fri Mar 28 05:02:27 2008
LMON: terminating instance due to error 484
Fri Mar 28 05:02:27 2008
System state dump is made for local instance
System State dumped to trace file /oracle/oracle/admin/UC/bdump/u2_diag_16093.trc Fri Mar 28 05:02:29 2008
Errors in file /oracle/oracle/admin/UC/bdump/u2_diag_16093.trc:
ORA-00484: LMS* process terminated with error
Fri Mar 28 05:02:29 2008
Trace dumping is performing id=[cdmp_20080328050227] Fri Mar 28 05:02:32 2008
Instance terminated by LMON, pid = 16097
… …
根据 LMON 超时的错误表现，导致 CLUSTER 异常踢出节点的原因，首先对如下方面考虑： 1． 操作系统 CPU/内存使用异常，导致请求不到所需资源，访问超时造成
2． 后台存储系统的 I/O 请求出现挂起，导致对数据文件（如：控制文件等）的访问挂起超时造成
3． 网络出现中断或阻塞，导致 LMON 通信异常，造成超时
4． ORACLE 软件在某些情况下处理异常（BUG） 可能性分析一：操作系统 CPU/内存使用异常状况的
操作系统方面。经检查对应的时间段内，处理器与内 存的使用均表现正常。在应用方面也没有新的动作操作。
可能性分析二：后台存储系统的 I/O 请求出现挂起的
后台存储导致数据库挂起、请求超时造成 CLUSTER 异常并进行 reconfiguration 动作的案例，我们遇到 过两例，分别为：
◆ 因为 AIX OS 漏洞造成存储驱动数据通讯异常，导致节点错误被踢出
◆ 因为存储系统程序本身的 BUG，造成高数据并发访问请求时的 CKPT 进程访问控制文件挂起（在 OS 端无错误，因为 I/O 请求无响应），最终导致数据库内部访问延时的超时定义被触发（详细说明见下
面部分），数据库节点关闭，导致节点错误被踢出
本次事件由于没有关于存储的监控或异常日志，无法判断是否有可能由此问题造成错误。但这个方面的检 查，仍然值得考虑。理由：我们在 LMON 的日志中发现，LMON 访问超时 900 秒，当时 LMON 访问的 数据文件为数据库控制文件。
逻辑结构图如下：
对应的超时时间为 900 秒，符合 CKPT 的超时定义，因此引起了我们的注意。关于 CKPT 方面的资料， 我们介绍如下：
■ CKPT 进程每 3 秒更新一次控制文件，这个操作我们可以成为“心跳”。CKPT 进程将为每一个实例 写唯一的一个数据块在控制文件头部， 通过这个信息维护心跳，成为“检查点进程记录”。当然在单
节点数据库也存在此信息。LMON 给每个 LMON 进程发送控制与状态信息。
在数据库内部，这些信息的接收具有 TIMEOUT 超时设定。如果信息发送失败或者出现接收到空信息，那 么 reconfiguration 动作将被触发。
■ LMON 在数据库通过内部参数 _cgs_send_timeout 定义超时，缺省为 300 秒。
■ CKPT 在数据库通过参数“ _controlfile_enqueue_timeout”定义超时，缺省为 900 秒。
本次的 LMON 进程日志 显示， CGS 超 时 条 件被触发 是本 次问题发 生的 触发条件 ， U1 的 日 志 u1_lmon_9208.trc 部分见下：
Begin DRM(41)
*** 2008-03-28 04:36:52.893 <<- - CLOCKTIME BEGIN
sent syncr inc 4 lvl 1097 to 0 (4,0/31/0) sent synca inc 4 lvl 1097 (4,0/31/0) sent syncr inc 4 lvl 1098 to 0 (4,0/34/0) sent synca inc 4 lvl 1098 (4,0/34/0) sent syncr inc 4 lvl 1099 to 0 (4,0/36/0) sent synca inc 4 lvl 1099 (4,0/36/0)
… …
sent synca inc 4 lvl 1104 (4,0/38/0)
*** 2008-03-28 04:51:54.355 <<- - 300S TIMEOUT TRIGGED kjfcdrmrfg: SYNC TIMEOUT (610433, 609532, 900), step 31
… …
而在 DIAG 进程的日志中可以发现，LMON 当时在访问控制文件，如下信息：
OSD pid info: Unix process pid: 9208, image: oracle@cupd25k-c (LMON) Dump of memory from 0x0000000402541A38 to 0x0000000402541C40
… …
Repeat 23 times
(FOB) flags=2 fib=5949008e0 incno=0 pending i/o cnt=0 fname=/dev/vx/rdsk/oradgUC/lv_uc_ctl3
fno=2 lblksz=4 fsiz=98499024
(FOB) flags=2 fib=594900540 incno=0 pending i/o cnt=0 fname=/dev/vx/rdsk/oradgUC/lv_uc_ctl2
fno=1 lblksz=4 fsiz=98499024
(FOB) flags=2 fib=5949001a0 incno=0 pending i/o cnt=0 fname=/dev/vx/rdsk/oradgUC/lv_uc_ctl1
fno=0 lblksz=4 fsiz=98499024
OSD pid info: Unix process pid: 9208, image: oracle@cupd25k-c (LMON) Dump of memory from 0x0000000402541A38 to 0x0000000402541C40
… …
Repeat 23 times
(FOB) flags=2 fib=5949008e0 incno=0 pending i/o cnt=0 fname=/dev/vx/rdsk/oradgUC/lv_uc_ctl3
fno=2 lblksz=4 fsiz=98499024
(FOB) flags=2 fib=594900540 incno=0 pending i/o cnt=0 fname=/dev/vx/rdsk/oradgUC/lv_uc_ctl2
fno=1 lblksz=4 fsiz=98499024
(FOB) flags=2 fib=5949001a0 incno=0 pending i/o cnt=0 fname=/dev/vx/rdsk/oradgUC/lv_uc_ctl1
fno=0 lblksz=4 fsiz=98499024
kjfsprn: dmap ver 4 (step 0)
DEFER MSG QUEUE ON LMD0 IS EMPTY SEQUENCES:
0:0.0 1:870037.0
DEFER MSG QUEUE ON LMS0 IS EMPTY SEQUENCES:
… …
DEFER MSG QUEUE ON LMS5 IS EMPTY SEQUENCES:
0:0.0 1:3464186.0
而此错误在高负载和锁请求频繁时发生，可以认为本次错误与网络拥塞无关。 可能性分析四：ORACLE 代码处理异常（BUG）
我们在分析最终认为，此种情况的可能性为 90%，不排除有其它原因（如 I/O HANG）导致 ORACLE 数据库对应的代码出错。不管起因如何，ORACLE 在 10.2.0.2 版本上，在本次事件的异常情况下处理， 在代码上存在缺陷。
理由一：DRM 检查未完成
DRM（dynamic resource mastering）功能在 ORACLE9.2 版本上存在但未被激活，因此只有 10G 版本存在此错误。几乎可以肯定的是，DRM 的轮询功能未能正常完成，应该是 ORACLE 本身对异常的处 理发生错误。
理由二：KJCDRMCFG 函数出现报错导致 LMON 异常
ORACLE 10.2.0.1~10.2.0.3 在 KJCDRMCFG 上面有很多 BUG，在高版本 10.2.0.4 上大部分已
经修复。此函数主要功能等待接收动态资源 REMASTER 信息。
三、结论、解决方案与建议
根据本次分析，我们得到的结论是：因为后台磁盘 I/O 挂起或其它异常原因，导致数据库在应用请求 不是在高负载情况下出现了异常，导致 DRM 过程中 CGS 超时条件被触发。
而此种超时，是由于 DRM 部分的处理代码，未能正确处理这部分异常造成，属于 ORACLE 软件的 BUG 类别。
修复建议：DRM 功能关闭或进行软件升级
此错误由 DRM 功能引起，因此可以选择将 DRM 功能关闭，将不再出现此错误。使用如下内部参数 关闭 DRM 功能：
1. _gc_integrity_checks = false
2. _gc_affinity_time=0
（DRM 在 ORACLE 10GR2 上生效）
3.2.1 关于DRM作用 DRM 在 10gr2 上被打开。每一个数据块在 RAC 下面均有一个主节点具有控制权。此节点将拥有此数
据块的锁资源。其它节点对此数据块的请求将进入请求队列。而决定数据块在那个节点上具有控制权及切 换，将有 DRM 轮询负责完成。DRM 将使 remaster 变快，提升了 RAC 的性能。
关闭 DRM 将导致 reconfiguration 动作比正常动作慢。同时，关闭 DRM 将因为数据块的 remaster 功能的关闭，损失部分数据库性能（大约 2～5%）。但关闭 DRM 功能不会有其它的负面作用。
对应的超时时间为 900 秒，符合 CKPT 的超时定义，因此引起了我们的注意。关于 CKPT 方面的资料， 我们介绍如下：
■ CKPT 进程每 3 秒更新一次控制文件，这个操作我们可以成为“心跳”。CKPT 进程将为每一个实例 写唯一的一个数据块在控制文件头部， 通过这个信息维护心跳，成为“检查点进程记录”。当然在单
节点数据库也存在此信息。LMON 给每个 LMON 进程发送控制与状态信息。
在数据库内部，这些信息的接收具有 TIMEOUT 超时设定。如果信息发送失败或者出现接收到空信息，那 么 reconfiguration 动作将被触发。
■ LMON 在数据库通过内部参数 _cgs_send_timeout 定义超时，缺省为 300 秒。
■ CKPT 在数据库通过参数“ _controlfile_enqueue_timeout”定义超时，缺省为 900 秒。
本次的 LMON 进程日志 显示， CGS 超 时 条 件被触发 是本 次问题发 生的 触发条件 ， U1 的 日 志 u1_lmon_9208.trc 部分见下：
Begin DRM(41)
*** 2008-03-28 04:36:52.893 <<- - CLOCKTIME BEGIN
sent syncr inc 4 lvl 1097 to 0 (4,0/31/0) sent synca inc 4 lvl 1097 (4,0/31/0) sent syncr inc 4 lvl 1098 to 0 (4,0/34/0) sent synca inc 4 lvl 1098 (4,0/34/0) sent syncr inc 4 lvl 1099 to 0 (4,0/36/0) sent synca inc 4 lvl 1099 (4,0/36/0)
… …
sent synca inc 4 lvl 1104 (4,0/38/0)
*** 2008-03-28 04:51:54.355 <<- - 300S TIMEOUT TRIGGED kjfcdrmrfg: SYNC TIMEOUT (610433, 609532, 900), step 31
… …
而在 DIAG 进程的日志中可以发现，LMON 当时在访问控制文件，如下信息：
OSD pid info: Unix process pid: 9208, image: oracle@cupd25k-c (LMON) Dump of memory from 0x0000000402541A38 to 0x0000000402541C40
… …
Repeat 23 times
(FOB) flags=2 fib=5949008e0 incno=0 pending i/o cnt=0 fname=/dev/vx/rdsk/oradgUC/lv_uc_ctl3
fno=2 lblksz=4 fsiz=98499024
(FOB) flags=2 fib=594900540 incno=0 pending i/o cnt=0 fname=/dev/vx/rdsk/oradgUC/lv_uc_ctl2
fno=1 lblksz=4 fsiz=98499024
(FOB) flags=2 fib=5949001a0 incno=0 pending i/o cnt=0 fname=/dev/vx/rdsk/oradgUC/lv_uc_ctl1
fno=0 lblksz=4 fsiz=98499024
OSD pid info: Unix process pid: 9208, image: oracle@cupd25k-c (LMON) Dump of memory from 0x0000000402541A38 to 0x0000000402541C40
… …
Repeat 23 times
(FOB) flags=2 fib=5949008e0 incno=0 pending i/o cnt=0 fname=/dev/vx/rdsk/oradgUC/lv_uc_ctl3
fno=2 lblksz=4 fsiz=98499024
(FOB) flags=2 fib=594900540 incno=0 pending i/o cnt=0 fname=/dev/vx/rdsk/oradgUC/lv_uc_ctl2
fno=1 lblksz=4 fsiz=98499024
(FOB) flags=2 fib=5949001a0 incno=0 pending i/o cnt=0 fname=/dev/vx/rdsk/oradgUC/lv_uc_ctl1
fno=0 lblksz=4 fsiz=98499024
kjfsprn: dmap ver 4 (step 0)
DEFER MSG QUEUE ON LMD0 IS EMPTY SEQUENCES:
0:0.0 1:870037.0
DEFER MSG QUEUE ON LMS0 IS EMPTY SEQUENCES:
… …
DEFER MSG QUEUE ON LMS5 IS EMPTY SEQUENCES:
0:0.0 1:3464186.0
而此错误在高负载和锁请求频繁时发生，可以认为本次错误与网络拥塞无关。 可能性分析四：ORACLE 代码处理异常（BUG）
我们在分析最终认为，此种情况的可能性为 90%，不排除有其它原因（如 I/O HANG）导致 ORACLE 数据库对应的代码出错。不管起因如何，ORACLE 在 10.2.0.2 版本上，在本次事件的异常情况下处理， 在代码上存在缺陷。
理由一：DRM 检查未完成
DRM（dynamic resource mastering）功能在 ORACLE9.2 版本上存在但未被激活，因此只有 10G 版本存在此错误。几乎可以肯定的是，DRM 的轮询功能未能正常完成，应该是 ORACLE 本身对异常的处 理发生错误。
理由二：KJCDRMCFG 函数出现报错导致 LMON 异常
ORACLE 10.2.0.1~10.2.0.3 在 KJCDRMCFG 上面有很多 BUG，在高版本 10.2.0.4 上大部分已
经修复。此函数主要功能等待接收动态资源 REMASTER 信息。
三、结论、解决方案与建议
根据本次分析，我们得到的结论是：因为后台磁盘 I/O 挂起或其它异常原因，导致数据库在应用请求 不是在高负载情况下出现了异常，导致 DRM 过程中 CGS 超时条件被触发。
而此种超时，是由于 DRM 部分的处理代码，未能正确处理这部分异常造成，属于 ORACLE 软件的 BUG 类别。
修复建议：DRM 功能关闭或进行软件升级
此错误由 DRM 功能引起，因此可以选择将 DRM 功能关闭，将不再出现此错误。使用如下内部参数 关闭 DRM 功能：
1. _gc_integrity_checks = false
2. _gc_affinity_time=0
（DRM 在 ORACLE 10GR2 上生效）
3.2.1 关于DRM作用 DRM 在 10gr2 上被打开。每一个数据块在 RAC 下面均有一个主节点具有控制权。此节点将拥有此数
据块的锁资源。其它节点对此数据块的请求将进入请求队列。而决定数据块在那个节点上具有控制权及切 换，将有 DRM 轮询负责完成。DRM 将使 remaster 变快，提升了 RAC 的性能。
关闭 DRM 将导致 reconfiguration 动作比正常动作慢。同时，关闭 DRM 将因为数据块的 remaster 功能的关闭，损失部分数据库性能（大约 2～5%）。但关闭 DRM 功能不会有其它的负面作用。