案例:log file sync等待引起的RAC 挂起（HANG）

客户的问题

用户系统有一个每隔1分钟执行的工作任务（JOB），通常会在1左右秒结束。 但是在最近发生过2次问题：由于等待”log file sync”事件，导致该工作任务（JOB）的会话等待几十分钟，不能正常完成。 发生问题的时间如下：

用户的数据库环境信息如下：

澄清问题

通过用户的描述，我们可以判断本次问题关键点是等待”log file sync”事件产生的原因。 为了确认问题发生时的状况，我们需要确认用户提供的日志文件，性能相关的AWR、ASH等参考资料，看看是不是能够找到相关的线索，定位问题。

什么是’log file sync’等待事件？

首先，我们想要明确一下什么是’log file sync’等待事件，以下是MOS 文档中对该等待事件的描述：

简而言之，就是前台进程在等LGWR进程工作的完成（或完成通知）。

信息收集(Data Collection)

该用户相对比较专业，所以提供了基本调查所需要的资料：

为了进一步确认发生的事件详细，我们从头一个接一个地确认资料。

告警日志（alert log）

首先查看问题发生期间，各个实例相关的警告日志输出内容:

根据上面告警日志的输出，RAC的三个节点（本次问题发生在节点1），在问题发生期间（2/22 10:17～10:57）并无异常输出，而Mon Feb 27 06:07之后无输出内容，所以问题发生期间（2/27 07:23～07:53）也无异常输出。 而且日志文件切换（LGWR switch）间隔好几个小时，所以切换并不频繁。 （标准建议是日志切换 间隔在15 ~ 20 分钟以上一次） 所以，仅仅根据告警日志（alert log），并没有找到什么线索。

下面我们以2/27问题发生时的数据进行分析AWR和ASH等其他资料的输出信息。

AWR报告内容

用户提供的AWR快照的间隔为1小时的报告，而问题发生期间为2/27 07:23～07:53仅半小时，AWR快照的间隔相对较长，对问题分析可能不会那么准确，但是可以作为参考。

摘要信息

查看节点1的AWR 报告：

通过AWR的摘要信息，我们可以看到数据库及服务器的基本状况。 其中，CPU数有10个，DB Time为158.54 (mins)，虽然有一点长，但是并不是特别的突出（没有发生问题的DB Time也差不多，有时甚至更长）。

等待事件

但是Top 10的前台等待事件中，”log file sync”等待成为最上位的等待事件（占DB Time的82%），并且等待总时间（Total）为7802s （约130 mins），平均等待（Avg ）为356 ms,显然是不正常的。 （通过其他AWR报告看到，正常时”log file sync”的平均等待Avg 为2ms）

根据上面的输出，可以看到前台的”log file sync”等待事件比较长，但是后台的”log file parallel write”等待事件却比较短（Total =1 s Avg =0 ms）。 所以，IO 方面的性能应该没有什么问题。

实例统计信息

我们再查看一下数据库实例的redo相关的各种统计信息。

首先看看应用程序 commit/rollback 情况。

其衡量方法一般为比较 user commit/rollback 同 user calls 比值的平均值， 即”user calls/(user commits+user rollbacks)” 本次平均值为20= 19.93/(0.05+0.95) ，commit 稍微有点频繁，但是猜测也不应该引起非常严重的整体数据库问题。 （通常，我们期望 user calls/user commit 大于 25；user calls/(user commits+user rollbacks)大于30。）

对于上面的统计信息，部分重要统计值的基本含义如下:

其他关于各统计信息的意义，大家可以参考官方Reference在线文档。

参考：

Database Reference 11.2 http://docs.oracle.com/cd/E11882_01/server.112/e40402/stats002.htm#i375475 >Statistics Descriptions

根据统计信息，看到了什么？

根据上面的统计信息的输出，我们可以看到用户的环境有以下的输出：

“redo synch poll writes”、”redo synch time overhead”和“redo write broadcast ack time”虽然都有输出，但是其值并不太高，说明不了什么问题。貌似LGWR并没有什么问题。。。

日志文件切换（LGWR switch）状况

根据上面的输出，在这段AWR报告期间内，并没有发生日志文件切换（LGWR switch）。

对于AWR报告的分析也就是这些了，至此，我们并没有明确问题的原因。

注：

对于"log file sync"等待问题，AWR等其他信息也可以参考MOS文档Doc ID 1376916.1。 参考： Troubleshooting: 'Log file sync' Waits (Doc ID 1376916.1)

下面我们分析一下ASH相关的信息。

ASH报告内容

由于用户并没有提供ASH的Dump信息，只提供了ASH报告，所以我们仅看一看ASH报告的相关信息。

通过ASH报告可以看到log file sync等待占据了大量时间，很多会话在等待log file sync，却依然没有什么原因的线索。

根据AWR 和ASH分析从数据库全体性能的角度，并没有找到什么突破性的进展，我们只能寄希望于日志文件了。

日志文件（lgwr*）

因为是和LGWR进程相关的问题，所以我们选择先看一看在这期间lgwr*相关的日志文件。

根据上面的输出，我们可以知道2/27 7:23时间点LGWR进程是以polling方式工作的。（关于LGWR进程的工作方式我们在之后【LGWR进程的工作方式（通知方法）】中进行介绍）

日志文件（dia0）

我们知道11g以后的版本中，Oracle增加了一个叫DIA0的进程，用于检测挂起(HANG)、解决死锁等问题。在系统异常时，常常会输出一些非常有用的信息。 所以，我们下一步查看DIA0的进程的日志文件。

SID1_dia0_22304_1.trc:

根据dia0进程的输出，我们可以看到7个用户进程的等待事件是’log file sync’，并且等待LGWR进程；而LGWR进程的等待事件是’rdbms ipc message’ 。

※关于等待事件’rdbms ipc message’ ：

表示后台进程处于空闲状态，等待从前台进程发送的IPC消息以执行一些工作

通过上面的输出出现的状况是，用户进程在等待LGWR进程工作的完成，而LGWR进程则在等待前台进程的工作指示。 似乎有一点不合理是不是？我们暂且放置一下，接着看其他的日志文件。

SID1_dia0_22304_base_1.trc：

通过上面SID1_dia0_22304_base_1.trc的输出，我们同样可以看到和前一个日志文件同样的内容：用户进程的等待事件是’log file sync’，并且等待LGWR进程；而LGWR进程的等待事件是’rdbms ipc message’ 。 并且可以看到某用户进程和LGWR进程的Short stack dump即在这个过程中执行的函数：用户进程在执行sltrusleep <- cold_kcrf_commit_force <- kcbdsy；LGWR进程在执行skgpwwait <- skgpwwait <- ksliwat。 对于Oracle的执行函数，也许一般DBA用户可能并不会了解，但是这个不重要，我们可以暂时搁置。

理清问题后的调查（Research ）

通过上面对资料的分析，我们基本上对发生的问题大致了解了，现在的焦点又回到上一个问题：

用户进程在等待LGWR进程工作的完成，而LGWR进程则在等待前台进程的工作指示，这到底是怎么个情况？是个什么状态？

在继续解决这个问题前，我们先了解一下LGWR进程的工作方式：

LGWR进程的工作方式（通知方法）

在11.2版本之后，LGWR进程对前台进程（foreground processes）Commit动作完成的通知方法包括2种：

Post/wait方式能够使前台进程第一时间知道LGWR写重做日志已经完成，所以能够提供单个前台进程更好的响应时间； 而Polling 方式能够减少LGWR进程的工作量和CPU的使用，一定程度避免LGWR进程上的瓶颈（尤其是当多个会话并发地同时commit时，Polling能够减少LGWR通知前台进程所消耗的CPU时间），所以能够提供更好的整体性能。

通常来讲，当系统负荷比较低时，Post/wait方式会工作的更好；当系统负荷比较高时，Polling方式则会工作的更好。

对于Post/wait方式和Polling 方式的控制，11.2版本引入了隐含参数”_use_adaptive_log_file_sync”进行控制。 可以通过以下SQL文查看该隐含参数的相关信息：

该参数可选择的设定值有FALSE、TRUE和POLLING_ONLY。 各值的含义如下：

在11.2.0.1 和 11.2.0.2 版本默认为FALSE;11.2.0.3以后的版本默认为TRUE;

确认用户环境

确认用户环境相关的设定，用的是默认值TRUE，即Adaptive Log File Sync功能有效。

试想，如果在LGWR进程通知方法使用Polling 方式时，当LGWR进程的commit动作写完成后，LGWR进程就会等待前台进程的工作指示，但是不会通知用户该commit动作已经完成；用户进程定期地休眠（sleep）和轮询（poll）检查LGWR写重做日志是否完成，如果休眠（sleep）和轮询（poll）过程中有什么问题的话，也许就会出现前面的状态：（仅仅是基于现阶段内容的假设）

用户进程在等待LGWR进程工作的完成，而LGWR进程则在等待前台进程的工作指示。

暂时回避方法

由于某些原因导致Oracle数据库软件在LGWR进程使用Polling 方式时有问题，或对于11.2.0.3开始才正式打开的Adaptive Log File Sync功能有问题，都有可能导致这次问题。 所以，作为为了进一步区分问题原因，我们首先考虑到的是通过设定隐含_use_adaptive_log_file_sync 为FALSE，来看看是否能够避免这次现象。 （事实证明在用户环境这个回避方法确实有效。）

原因进一步定位

显然这次现象的动作不像是正常期待的动作，所以为了找到根本原因，我们考虑可能是由于Bug引起的，再次确认用户的DB版本信息为PSU11.2.0.4.5 。 通过之前的分析内容和以下的MOS文档，我们很快可以定位问题可能是由于Bug 25178179导致的。

原因

前台进程在等待’log file sync’时，会执行kcrf_commit_force()函数，并使用”redo write broadcast ack time”的平均值来判断他们的轮询睡眠时间。 但是数据库以Polling方式写Redo日志时，由于Bug 25178179的影响内部函数计算错误，虽然实际的应答时间很少但是计算结果却很大（尤其当多个前台进程同时执行并满足特定条件时这种状况更容易发生），前台进程会依据错误计算的结果，改变轮询睡眠时间，导致部分前台进程处于睡眠状态不能够正常结束，从而表现为过长时间的“log file sync”等待。

而Bug 25178179的发生条件（症状）可以归类以下几点：

根据前面信息收集的内容，本次用户现象发生时基本满足了上面所有的条件； （虽然Short Stack中包含的函数是cold_kcrf_commit_force()，但从函数的功能来看，基本可以等同于kcrf_commit_force函数） 而用户的数据库版本为PSU11.2.0.4.5为Bug 25178179的影响范围，并且没有打Bug 25178179相关的补丁。 所以，可以断定本次现象是由于Bug 25178179引起的。

解决方法

为了解决这个问题，我们可以使用以下的任意方法：

知识点总结（KM）

通过本次案例， 我们详细描述了解决log file sync等待问题的思路和过程， 并涵盖了以下的知识点。

※Tips：其实案例的结果并不重要，重要的是找到结果的过程！！