用户系统有一个每隔1分钟执行的工作任务(JOB),通常会在1左右秒结束。 但是在最近发生过2次问题:由于等待”log file sync”事件,导致该工作任务(JOB)的会话等待几十分钟,不能正常完成。 发生问题的时间如下:
用户的数据库环境信息如下:
通过用户的描述,我们可以判断本次问题关键点是等待”log file sync”事件产生的原因。 为了确认问题发生时的状况,我们需要确认用户提供的日志文件,性能相关的AWR、ASH等参考资料,看看是不是能够找到相关的线索,定位问题。
首先,我们想要明确一下什么是’log file sync’等待事件,以下是MOS 文档中对该等待事件的描述:
简而言之,就是前台进程在等LGWR进程工作的完成(或完成通知)。
该用户相对比较专业,所以提供了基本调查所需要的资料:
为了进一步确认发生的事件详细,我们从头一个接一个地确认资料。
首先查看问题发生期间,各个实例相关的警告日志输出内容:
根据上面告警日志的输出,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快照的间隔为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并没有什么问题。。。
根据上面的输出,在这段AWR报告期间内,并没有发生日志文件切换(LGWR switch)。
对于AWR报告的分析也就是这些了,至此,我们并没有明确问题的原因。
注:
对于"log file sync"等待问题,AWR等其他信息也可以参考MOS文档Doc ID 1376916.1。 参考: Troubleshooting: 'Log file sync' Waits (Doc ID 1376916.1)
下面我们分析一下ASH相关的信息。
通过ASH报告可以看到log file sync等待占据了大量时间,很多会话在等待log file sync,却依然没有什么原因的线索。
根据AWR 和ASH分析从数据库全体性能的角度,并没有找到什么突破性的进展,我们只能寄希望于日志文件了。
因为是和LGWR进程相关的问题,所以我们选择先看一看在这期间lgwr*相关的日志文件。
根据上面的输出,我们可以知道2/27 7:23时间点LGWR进程是以polling方式工作的。(关于LGWR进程的工作方式我们在之后【LGWR进程的工作方式(通知方法)】中进行介绍)
我们知道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用户可能并不会了解,但是这个不重要,我们可以暂时搁置。
通过上面对资料的分析,我们基本上对发生的问题大致了解了,现在的焦点又回到上一个问题:
用户进程在等待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导致的。
而Bug 25178179的发生条件(症状)可以归类以下几点:
根据前面信息收集的内容,本次用户现象发生时基本满足了上面所有的条件; (虽然Short Stack中包含的函数是cold_kcrf_commit_force(),但从函数的功能来看,基本可以等同于kcrf_commit_force函数) 而用户的数据库版本为PSU11.2.0.4.5为Bug 25178179的影响范围,并且没有打Bug 25178179相关的补丁。 所以,可以断定本次现象是由于Bug 25178179引起的。
为了解决这个问题,我们可以使用以下的任意方法:
通过本次案例, 我们详细描述了解决log file sync等待问题的思路和过程, 并涵盖了以下的知识点。
※Tips:其实案例的结果并不重要,重要的是找到结果的过程!!