当前位置: 首页 > 数据库 > oracle >

OGG BUG引发的数据库故障

 首先在本文开始前介绍几个 Oracle 数据库中的概念。

LMS 进程:

实际上就是GCS(Global Cache Service Processes) 。这个是在RAC 环境中才会有的进程,负责管理集群的资源,并协调集群资源的访问。这里的资源主要指的是Buffer Cache 。

LMS 进程对于RAC 来说极为重要,因为集群的Cache Fusion 的动作由它来完成,如果它发生了故障,则集群的处理能力会受到很大的影响,严重的话可能导致数据库实例被集群驱逐。
    以下为官方描述:

The LMS process maintains records of the data file statuses and each cached block by recording information in a Global Resource Directory (GRD). The LMS process also controls the flow of messages to remote instances and manages global data block access and transmits block images between the buffer caches of different instances. This processing is part of the Cache Fusion feature.

LMD 进程:

Global Enqueue Service Daemon 。主要负责管理集群之间锁的使用。

以下是官方描述:

The LMD process manages incoming remote resource requests within each instance.

此进程对于集群来说也非常重要。它要协调节点之间对于lock 等的访问。

LMON:
Global Enqueue Service Monitor 。监控整个集群的排队与资源,并进行全局的排队操作的恢复

    以下是官方描述:
The LMON process monitors global enqueues and resources across the cluster and performs global enqueue recovery operations.

DIAG :

    Diagnostic Capture Process 。负责进行进程或者实例发生故障时,进行 dump 操作。会记录进程的执行堆栈以及进程的内存等信息。

接下来,分享一个实际生产环境中的故障,以及诊断处理的过程。

某客户使用的是一套HP-UX 小机下的11.2.0.3 的双节点RAC ,数据库节点1 上搭建了了OGG 进行数据的抽取。

2020 年3 月3 日,某客户核心数据库在上午运行极为缓慢,业务办理极为不畅。下午据反馈运行较为正常。

3 月4 日上午,出现出现了同样的状况。同时,节点1 的数据库软件安装目录不断有大量的写入动作,使得数据库软件目录有爆满的危险。此时客户要求我们进行介入。

首先,对于数据库软件的目录不断有大量写入的问题,按照时间将数据库节点1 的trace 目录文件进行了排序,结果如下:

可以看到有两个文件特别巨大,ora_26340.trc, ora_26241.trc 。Oracle 的trace 文件名中的数字实际上是操作系统的进程编号。

通过操作系统查看进程,发现这两个进程都是LOCAL=NO 的进程,即数据库用户连接到数据库时的会话进程。

通过数据库的视图gv$session_blockers 查看阻塞情况, 结果发现有两个会话持有的gc element 的latch 阻塞了大量的会话:

通过v$process 与v$session 查询,与进程26340 , 26241 对应。同时,这两个进程的连接的数据库用户是OGG 抽取所使用的用户,与客户确认之后,杀掉了这两个进程,并进行了重启OGG 服务的操作。经过此操作后,latch: gc element 的相关阻塞消失。同时,数据库软件安装目录的大量写入也消失了。

查看3 月3 日上午的AWR 报告,发现数据库的主要负载就是集群节点之间的数据交互与latch: gc element 等待,一次等待的时间多于600 毫秒, 数据库负载也极高:

其实这里也与gv$session_blockers 视图中的结果相对应。

   客户的DBA 反映3 月3 日出现了问题,自然,首先查看告警日志:

     Errors in file /oracle/diag/rdbms/testdb/testdb1/trace/testdb1_ora_23342.trc  (incident=1023790):

ORA-00600: internal error code, arguments: [15711], [4], [0xC000001C6FA6E798], [0xC000001C6FA91D28], [], [], [], [], [], [], [], []

Incident details in: /oracle/diag/rdbms/testdb/testdb1/incident/incdir_1023790/testdb1_ora_23342_i1023790.trc

 

可以看到进程23342 发生了ORA-00600 的错误。ORA-00600 很多情况下是Oracle 软件自身的bug 。查看这个trace 文件,文件头有如下内容:
   

 

其中的MODULE NAME: OGG-EXT 说明这个进程属于OGG 的抽取进程。

查看OGG 的ggserr.log ,发现确实有此错误:

2020-03-03 05:19:06  ERROR   OGG-00665  Oracle GoldenGate Capture for Oracle, ext_zj.prm:  OCI Error executing statement (status = 600-ORA-00600: internal error code, arguments: [15711], [4], [0xC000001C6FA6E798], [0xC000001C6FA91D28], [], [], [], [], [], [], [], []), SQL<SELECT TO_CHAR(startup_time, 'YYYY-MM-DD HH24:MI:SS') FROM gv$instance WHERE inst_id = 2>.

2020-03-03 05:19:07  INFO    OGG-00991  Oracle GoldenGate Capture for Oracle, ext_zj.prm:  EXTRACT EXT_ZJ stopped normally.

继续查看告警日志,发现有如下内容:

Errors in file /oracle/diag/rdbms/testdb/testdb1/trace/testdb1_lmhb_6033.trc  (incident=1020926):

ORA-29771: process USER (OSID 23254) blocks LMS0 (OSID 6025) for more than 70 seconds

Incident details in: /oracle/diag/rdbms/testdb/testdb1/incident/incdir_1020926/testdb1_lmhb_6033_i1020926.trc

Tue Mar 03 11:58:47 2020

Sweep [inc][1020926]: completed

Tue Mar 03 11:58:47 2020

USER (ospid: 23254) is blocking LMS0 (ospid: 6025) in a wait

LMHB (ospid: 6033) kills USER (ospid: 23254).

Please check LMHB trace file for more detail.

Tue Mar 03 12:07:26 2020

Non critical error ORA-48113 caught while writing to trace file "/oracle/diag/rdbms/testdb/testdb1/trace/testdb1_ora_23342.trc"

Error message:

Writing to the above trace file is disabled for now on...

Tue Mar 03 12:07:29 2020

Non critical error ORA-48113 caught while writing to trace file "/oracle/diag/rdbms/testdb/testdb1/trace/testdb1_lmd0_6023.trc"

 这里说的是LMS 进程被用户进程23254 所阻塞,阻塞的时间太长,LMON 进程把23254 进程杀掉了。这也是为什么客户反馈说3 月3 日下午业务运行良好, 因为阻塞的进程被LMON 进程杀掉了。

另外需要注意的是这个ORA-48113, 这个错误是: unable to write to stream file because of out of space condition , 也就是说,实例当时在尝试写trace ,但是磁盘上已经没有空间可以继续写入了。这是因为,Oracle 的DIAG 进程在dump 这两个进程,而这两个进程都是OGG 的相关进程,dump 的内容太多,已经把磁盘撑爆了。

 查看LMON 日志,有记录kill 的动作。

至此,故障的整个时间线就清楚了。

3 月3 日5 点15 分左右,OGG 抽取进程发生故障ORA-00600[15711] ,导致了两个进程异常。不幸的是,这两个进程持有了latch: gc element ,LMS 进程需要这个latch 才能进行数据的传递。这个latch 都是节点1 持有,这样是为什么gc cr grant 2-way 的等待时间如此之高。因为节点2 向节点1 申请读取数据块,但是节点1 的LMS 迟迟不能得到这个gc element 的latch 。对于这个ORA-00600[15711], MOS 也没有很多信息, 只有一个相关的文档: ORA-600 [15711] (Doc ID 370916.1) ,也没有相关的补丁提供。

如下链接可以参考此Oracle 错误:
     https://www.eygle.com/archives/2019/09/ora-00600_15711_ogg.html

接下来整个上午都因为这个gc element 的latch 业务都不能进行办理。直到中午11 点58 分左右, 数据库的LMON 介入,杀掉两个进程之后,数据库才恢复正常。

3 月4 日状况稍有不同,多了一个错误。也是在同样的时间点OGG 进程崩溃,错误有所不同:

2020-03-04 06:33:13  ERROR   OGG-00665  Oracle GoldenGate Capture for Oracle, ext_cslm.prm:  OCI Error executing statement (status = 600-ORA-00600: internal error code, arguments: [15711], [4], [0xC000001C6FA6FBE0], [0xC000001C6FA86D18], [], [], [], [], [], [], [], []), SQL<SELECT TO_CHAR(startup_time, 'YYYY-MM-DD HH24:MI:SS') FROM gv$instance WHERE inst_id = 2>.

2020-03-04 06:33:15  INFO    OGG-00991  Oracle GoldenGate Capture for Oracle, ext_cslm.prm:  EXTRACT EXT_CSLM stopped normally.

2020-03-04 06:33:23  ERROR   OGG-00665  Oracle GoldenGate Capture for Oracle, ext_ac20.prm:  OCI Error executing statement (status = 600-ORA-00600: internal error code, arguments: [15711], [4], [0xC000001C6FA9D158], [0xC000001C6FA97020], [], [], [], [], [], [], [], []), SQL<SELECT TO_CHAR(startup_time, 'YYYY-MM-DD HH24:MI:SS') FROM gv$instance WHERE inst_id = 2>.

2020-03-04 06:36:15  ERROR   OGG-00665  Oracle GoldenGate Capture for Oracle, ext_ab.prm:  OCI Error executing statement (status = 600-ORA-00600: internal error code, arguments: [15711], [4], [0xC000001C6FA8ADB8], [0xC000001C6FA9A9B0], [], [], [], [], [], [], [], []), SQL<SELECT TO_CHAR(startup_time, 'YYYY-MM-DD HH24:MI:SS') FROM gv$instance WHERE inst_id = 2>.

2020-03-04 06:38:17  ERROR   OGG-00665  Oracle GoldenGate Capture for Oracle, ext_kc21.prm:  OCI Error describe for query (status = 12805-ORA-12805: parallel query server died unexpectedly), SQL<SELECT TO_CHAR(startup_time, 'YYYY-MM-DD HH24:MI:SS') FROM gv$instance WHERE inst_id = 2>.

2020-03-04 06:38:17  INFO    OGG-00991  Oracle GoldenGate Capture for Oracle, ext_kc21.prm:  EXTRACT EXT_KC21 stopped normall

 3 月 4 日,我们是在下午 2 点客户上班之前杀掉了两个进程,所以,告警日志并未发现有杀进程的信息。但是, LMON, LMD 进程的 trace 文件中,有大量的 gc element 的相关告警。基本可以确认与 3 月 3 日状况类似。

3 月 4 日重启了 OGG ,做了杀进程的动作之后, 3 月 5 日业务与恢复了正常。

 Goldengate 的 ORA-12805 的错误,基本可以确认是OGG 的bug 。客户的OGG 版本恰好在此bug 影响的版本之列。

MOS 给出的解决方案是升级OGG 版本或者对OGG 打补丁

鉴于客户的数据库没有应用任何补丁,我们给出的建议是:应用此数据库版本的最新PSU , 并升级OGG 版本。

------分隔线----------------------------
  • 收藏
  • 挑错
  • 推荐
  • 打印