<< 返回文章列表

数据恢复|数据运维 RAC数据库频繁hang问题诊断案例

2017年12月26日
熊军
1285

【云和恩墨,提供7*24最专业的数据恢复(Oracle,MySQL,SQL server)服务,致力于为您的数据库系统做最后一道安全防护!服务热线:010-59007017-7030】数据恢复|数据库运维|性能优化|安全保障  


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

案例现象及概要
某客户的核心系统数据库是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中有如下重要信息。
image.png

省略部分内容
image.png

省略部分内容
image.png

故障详细分析
从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语句如下。
image.png

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

接下来,看看这个进程所阻塞的进程(orapid=40)的信息。

image.png

从上面的信息可以确认以下几点:
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这个关键后台进程也一直挂起。
image.png

省略部分内容
image.png

image.png

从上面的信息可以看到,资源的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比较匹配。
image.png

从上面的数据可以看到,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.”表明进程出现了异常。
image.png

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

会话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进程不能进行日志生成和写出,不能进行任何数据修改,短时间内堵塞了大量会话,同时数据库实例完全挂起。
image.png

*** 2014-01-09 12:25:06.624
image.png

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

有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引起的。
image.png

*** 2014-01-08 10:13:21.611
image.png

查看ASH数据
image.png

image.png

从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性能优化与诊断案例精选第十二章》