【新书连载】：RAC数据库频繁hang问题诊断案例

编辑说明：《Oracle性能优化与诊断案例精选》出版以来，收到很多读者的来信和评论，我们会通过连载的形式将书中内容公布出来，希望书中内容能够帮助到更多的读者朋友们。

熊军（老熊）

云和恩墨西区总经理

Oracle ACED，ACOUG核心会员

题记：数据库的问题大体上可以分为两类，一类是数据库真的出了问题，不能正常运行，甚至影响到业务的。另一类是潜在的问题，也就是性能问题。对于这两类问题的分析，有相同也有不同之处。我们通过具体的案例来说明。

某客户的核心系统数据库是2节点的Oracle RAC数据库， 版本为10.2.0.4，数据库主机平台为IBM AIX，数据量超过10TB。这套数据库在最近一段时间经常出现系统挂起的严重故障，严重影响了生产的运行。在近一个月内，几乎每天可能都会出现故障，甚至是在业务不繁忙的时候。本文主要分析了系统的故障原因，并提出了对应的解决方案，希望能给读者在故障诊断时提供一些思路。

下面是2014年1月7日早上8点至9点时间段的故障日志（为保护案例数据库的信息，将实际的数据库名字替换为orcl）。实例1日志信息。

Tue Jan  707:51:08 2014

ALTER SYSTEM ARCHIVE LOG

Tue Jan  7 07:51:08 2014

Thread 1cannot allocate new log, sequence 75616

Checkpointnot complete

Current log# 1 seq# 75615 mem# 0: dev/rlv9

Tue Jan  708:15:52 2014

PMON failed to delete process, see PMON trace file

Tue Jan  7 08:23:34 2014

WARNING:inbound connection timed out (ORA-3136)

Tue Jan  708:24:53 2014

Errors in file/u01/app/oracle10g/admin/orcldb/udump/orcldb1_ora_10503176.trc:

ORA-00604: error occurred at recursive SQL level 1

ORA-01013: user requested cancel of currentoperation

ORA-06512: at line 2

....省略部分内容......

Tue Jan  708:52:22 2014

Shutting down instance (abort)

License high water mark = 3510

Instance terminated by USER, pid = 5731764

Tue Jan  709:01:45 2014

Starting ORACLE instance (normal)

sskgpgetexecname failed to get name

早上7:51左右出现了“检查点未完成”而不能切换日志的信息，8:23左右出现会话不能登录的信息，而到8:52强制关闭了实例然后重启。

在数据库关闭之前，对数据库做了system state 转储，在跟踪文件orcldb1_ora_5727520.trc中有如下重要信息。

省略部分内容

省略部分内容

从system dump的信息，反映出以下几点。

1、oracle进程（orapid=207，ospid=5297410，session id=4339）持有一个cache buffers chains child latch，子latch号为40228，子latch的地址为：7000027ce79ac58。

2、这个进程阻塞了一个进程（orapid=40），阻塞时间长为3851秒。

3、这个进程上一个等待事件是磁盘单块读，到目前为止已经过了4456秒。system state dump是从2014年1月7日08:37:45开始的，那么4456秒之前即latch开始持有的时间是在2014年1月7日07:23:29至2014年1月7日07:28:29之间（由于system state dump本身需要消耗一定的时间，因此会有一定的时间误差，这个时间误差在5分钟之内）。

4、这个进程的是由数据库主机本机上的SQLplus连接上来的，正在执行的SQL语句如下。

这里很明显有一个异常，进程持有latch的时间过长。正常情况下latch持有时间在微秒级，而这个进程持有latch长达几千秒。这通常是由于进程异常或挂起所导致。

接下来，看看这个进程所阻塞的进程（orapid=40）的信息。

从上面的信息可以确认以下几点：

1、被阻塞的进程是CKPT进程，这是系统关键的后台进程——检查点进程。

2、CKPT进程由于等待cache buffers chains latch而被阻塞，被阻塞的时间长为3837秒，也就是在大约2014年1月7日07:33:48时被阻塞（由于system state dump需要消耗时间，所以可能有5分钟之内的时间误差）。

很显然，由于CKPT进程被长时间阻塞，将不能完成检查点工作。

Tue Jan  7 07:18:53 2014

Thread 1 advanced to log sequence 75613 (LGWR switch)

Current log# 3 seq# 75613 mem# 0: dev/rlv11

Tue Jan  7 07:31:01 2014

Thread 1 advanced to log sequence 75614 (LGWR switch)

Current log# 2 seq# 75614 mem# 0: dev/rlv10

Tue Jan  7 07:43:04 2014

Thread 1 advanced to log sequence 75615 (LGWR switch)

Current log# 1 seq# 75615 mem# 0: dev/rlv9

Tue Jan  7 07:51:08 2014

ALTER SYSTEM ARCHIVE LOG

Tue Jan  7 07:51:08 2014

Thread 1 cannot allocate new log, sequence 75616

Checkpoint not complete

Current log# 1 seq# 75615 mem# 0: dev/rlv9

由于一个实例的在线日志文件只有3组，从7:31开始，经过3次切换，就不能再切换了。不能切换日志就意味着不能进行任何数据更改。由于数据库设置有登录触发器，对登录信息进行记录，会涉及数据插入。在这样的情况下，用户登录也不能成功，会一直挂起（或者直至超时）。

由于CKPT挂起，这导致了SMON这个关键后台进程也一直挂起。

省略部分内容

从上面的信息可以看到，资源的GRANTED_Q队列中有进程2508016。这个进程正是CKPT进程，即CKPT进程以PROTECT READ模式持有资源，但是SMON进程需要以EXCLUSIVE模式来持有资源。这两种模式是不兼容的，因此SMON进程就被阻塞。

到目前为止，可以确定是由于异常的进程（orapid=207）长时间持有cache buffers chains childlatch，使得CKPT被长时间阻塞，导致不能完成检查点，最终导致不能进行任何数据更改和不能连接数据库。

导致系统故障的异常进程，其异常的原因，通常有：

（1）操作系统Bug导致，使得异常的进程不能调度。在trace文件中看到，使用procstack获取进程call stack失败，说明进程在操作系统一级异常，而不是在oracle内部存在spin或stuck hang的情况。

（2）Oracle的Bug，通过在MOS上查找，我们发现有如下Bug：Bug 6859515  Diagnostic collection may hang or crash theinstance，可能会有影响。

如何认定一个Bug与故障是匹配的？

我们需要从大量的日志和trace中去寻找。一般会去从diag进程的trace和system state dump中寻找：

在diag进程的trace文件中，我们发现现象与Bug 6859515比较匹配。

从上面的数据可以看到，ospid=5297410这个进程正是异常的持有latch的进程。这个进程在2014年1月7日07:24:56被请求转储，从时间上看这与该进程异常的时间点在2014年1月7日07:23:29至2014年1月7日07:28:29之间匹配。诊断转储是由orapid=46，ospid=1008052这个进程请求diag进程发起的。

“procstack:write（/proc/5297410/ctl）: The requested resource is busy.”表明进程出现了异常。

从上面的数据可以看到，orapid=46，ospid=1008052这个进程一直在等待TX事务行锁，这个进程同样是SQLplus程序连接数据库产生的进程，执行的SQL语句也与异常进程一样。这个进程被异常进程（即orapid=207）阻塞，阻塞大约是在08:37:45的5330秒之前，即07:08:55左右。

会话6122在等待事务锁，阻塞的会话是4339，即orapid=207的会话进程。由于SQL执行性能的原因，数据锁时间过长，因此会话6122即orapid=46的进程向diag进程申请发起一个对orapid=207进程的转储操作，这样就触发了Bug，导致orapid=207的进程异常。

2014年1月9日12:30左右，数据库节点2的实例再次发生hang故障。从diag的信息来看，同样是因为diag触发Bug导致进程异常。异常进程持有redo copy latch使得其他所有进程，包括LGWR进程不能进行日志生成和写出，不能进行任何数据修改，短时间内堵塞了大量会话，同时数据库实例完全挂起。

*** 2014-01-09 12:25:06.624

在hang analyze的结果中可以看到，正是3252 这个会话产生了阻塞。

有416个会话在等待6568这个会话，即6568会话阻塞了416个进程，而6568会话在等待latch：redo allocation，而6568会话正是被3252会话阻塞。6568会话是LGWR进程。毫无疑问，LGWR进程不能持有redo allocation latch，将不能写redo到日志文件，也就不能完成事务提交，所以在短时间内会产生大量的进程在等待log file sync，即等待LGWR完成日志写入。

接下来再看看2014年1月8日10:13左右开始，节点2数据库实例很慢然后发生hang故障，这同样是diag触发Bug引起的。

*** 2014-01-08 10:13:21.611

查看ASH数据

从ASH数据可以看到，10:13:15系统还处于正常状态，仅仅在10秒之后（在AWR中的ASH数据时间间隔为10秒），即10:13:25系统就产生了大量的阻塞。diag导致Bug被触发是在10:13:21这个时间。

经过上述的深入分析，我们判断近段时间故障频发的主要原因是触发了Oracle的Bug 6859515，这个Bug为：Diagnostic collection may hang orcrash the instance。具体如下所示。

（1）当Oracle的一个进程在等待某个资源（最常见的是事务锁，即TX锁）时间过长时，会向diag进程发起转储请求。diag进程对引起堵塞的进程发起转储（dump）操作，主要包括操作系统层面进程的信息、进程的call stack、在Oracle内部进程的状态和会话的状态等非常详细的数据，用于阻塞问题的诊断。

（2）diag进程会通过操作系统级的命令来收集被诊断进程的call stack信息，包括gdb调试工具或procstack等（不同的操作系统有所不同）。gdb或procstack工具在取进程的call stack信息时是不安全的，可能会造成进程异常或挂起。如果此进程当时持有latch等重要资源，这些重要资源将不会被释放。因为进程只是异常或挂起，没有消失，因此Oracle的pmon进程不会清理和释放这些被一直占有的重要资源。

latch是Oracle内部一种低级的内存锁，使用非常频繁。通常latch的持有时间在毫秒级以下，如果进程长时间持有latch，将会使其他请求latch的进程也会一直挂起。最终关键的后台进程，如CKPT、LGWR等进程也会由于请求此latch获取无法得到响应而挂起，关键是后台进程的挂起会导致数据库挂起。

（3）异常进程持有的latch不同，系统的故障现象有所不同。

1）如果是持有cache buffer chains child latch，由于这种latch的子latch数量很多，每个子latch只是保护部分数据块头，所以只有在访问这个被持有的子latch保护的数据块时才会被阻塞（挂起）。进程一直会等待latch: cachebuffer chains，随后会出现buffer busy waits、gc buffer busy等与数据块访问相关的等待。被挂起的进程如果处于事务之中，又会出现TX锁等待。如果这个latch保护的数据块是脏块，会导致DBWn（数据库写进程）进程等待这个latch而挂起。CKPT进程如果需要访问这个latch也会挂起，最终结果会导致不能完成检查点，日志不能切换，数据库挂起。cachebuffer chains child latch数量众多，如果是由于一个child latch被异常进程持有一直到数据库挂起，历时时间较长，甚至可能达到数小时。

2）如果是持有redo copy latch、redo allocation latch等与redo相关的latch，由于这种latch只有一个或者是子latch数量极少，同时使用极为频繁，因此在短时间内LGWR这样的关键后台进程会挂起，大量进程出现log file sync等待，LMS等关键进程出现gcs log flush sync等待而挂起。其最终结果是短时间内出现大量进程挂起和系统挂起。

3）如果是持有shared pool latch、library cache latch等与SQL解析相关的latch，同样会在短时间内出现大量与解析相关的等待，导致大量进程挂起和系统挂起。

（4）在gdb或procstack导致进程异常的情况下，进程可能会被KILL命令杀掉，也可能不能被杀掉。如果进程能够被杀掉，那么数据库pmon进程会自动清理异常进程占用的资源，系统能够恢复正常。如果进程不能被杀掉，或者是pmon进程本身已经被阻塞而挂起，这样杀进程也不能使系统恢复正常，需要强制重启数据库才能使系统恢复运行。

要解决此问题，可以安装数据库补丁，补丁为8929701：TRACKING Bug FOR 6859515 ON AIX。安装这个补丁后，diag进程不再通过操作系统的gdb或procstack等工具获取被诊断进程的call stack等信息，而是改为使用Oracle内部的oradeBug short_stack命令来获取。如果不能打补丁，可以将隐含参数"_ksb_disable_diagpid"设置为TRUE作为临时解决方案。注意，这种设置之后，将不能自动收集进程诊断信息，这样当出现一些其他问题时可能会缺乏一些有效的诊断数据。这个案例最终通过打补丁解决了问题。

通过这个案例，我想有如下的两点，对我们有些帮助。

1）很多朋友在安装数据库时，没有安装任何补丁。有些有经验的DBA，也只是安装了最新的PSU补丁，实际上有些对系统影响大的补丁并不在PSU中。比如在MOS文档“11.2.0.4 Patch Set - Availability and Known Issues (文档 ID 1562139.1)”中就列出了11.2.0.4这个版本中发现的出现频繁比较高的Bug。在可能的情况下，要把提到的Bug的补丁都打上。

2）在分析问题时，alert日志、system state dump、hang analyze trace、diagnostic进程trace和ASH（activesession history）数据都是很有用的信息来源。多种数据交叉参考，可以避免单一数据形成的信息量不足没有思路，或者单一数据形成错误结论。

节选自《Oracle性能优化与诊断案例精选第十二章》