Oracle DRM kjfcdrmrfg 超时错误分析一例

实例节点的警告日志,错误如下:

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 访问的 数据文件为数据库控制文件。

逻辑结构图如下:

cgs_IMR
对应的超时时间为 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 功能不会有其它的负面作用。

Comment

*

沪ICP备14014813号

沪公网安备 31010802001379号