又见Log File Sync~

上周四,应用部门中负责数据库维护的同事发来求助邮件,所属业务后台数据库出现严重性能异常,希望帮忙协助一下排查一下数据库问题,应用部门监控到了具体的异常时间点,如下图所示:

log_file_sync_1024-1

图中涉及到了两类数据库关键性能指标,1.DB_TIME,2.Active Session数据,从同事中邮件中反馈得知,24日的 16:00开始 数据库DB_TIME开始飙升,但是图中的ACTIVE_SESSION显示的异常事件点为14:00-15:00左右。两类指标异常的时间点并不吻合。具体数据库发生了什么? 登录到数据库后,查看了具体的信息:

ASH信息:

从ASH中看到,从13:57分开始,数据库中陆续出现log file sync等待事件,与同事提供的监控数据基本吻合。

1026-2

 

log file sync等待在15:06时自行恢复,数据库ACTIVE_SESSION数随之降低,恢复正常。

 

1026-3

此时间段内,等待事件分布数量如下,可以看到log file sync等待是数据库活动会话激增的主要矛盾,从而造成了数据库在此时间段内产生了性能瓶颈。

1026-4

平均等待毫秒数信息:

1026-5

找到了主要矛盾后,我们再来分析,为何log file sync本身有何异常?

服务器存储IO链路出现异常?

通过观察操作系统IO指标,IO性能并没有出现严重异常现象

1026-6

通过AWR报告中正常与异常differ对比,log file parallel write性能指标也没有出现明显的异常波动,然而log file sync出现严重性能下降,也就是说,并没有慢在日志文件写磁盘的环节中

1026-7

虽然造成log file sync有诸多原因,但是看到上面这个differ awr后,我不禁想到了一个可能性,随即去看了lgwr.trc 后台进程trace文件(有经验的朋友到这里可能都猜到了我要找什么关键字)

1026-8

从lgwr trace文件中看到,LGWR进程在10月16日时触发了模式切换,有原有默认的POST/WAIT切换至了POLLING状态,触发了LGWR的自适应切换。

什么是LGWR的POST/WAIT与POLLING模式?

1026-9

ORACLE从11G开始,为lgwr写日志引入了polling机制,而在以前只有post/wait机制。
同时引入了一个隐含参数,”_use_adaptive_log_file_sync”,即在两个机制之间自适应的切换。在11.2.0.3以下,该参数的默认值为false,即只启用post/wait机制。

从11.2.0.3开始,该参数的默认值为true,即Oracle会在post/wait机制和polling机制自适应。

Post/wait进制下,lgwr进程在写完log buffer中的改变向量后,立刻通知待commit的进程,因此log file sync等待时间短,但lgwr相对来说,负担要重一些。毕竟12C以下lgwr进程只有1个,当同时commit的进程比较多的时候,通知commit的进程也是一种负担。

Polling模式下,待commit的进程,通知lgwr进程进行写入操作后,会进入sleep环节,并在timeout后去看是否log buffer中的内容被写入了磁盘,lgwr进程不再单独通知待commit的进程写已经完成。Polling机制下,解放了一部分lgwr的工作,但是会带来待commit的进程长时间处于log file sync等待下。对于交易型的系统而言,该机制是不适用的,也就是说当切换到polling模式下时,很容易引起log file sync等待而影响交易的响应时间。

为避免后续LGWR再次触发异常,将”_use_adaptive_log_file_sync”参数调整至false,避免lgwrj进程再次触发模式切换。

ALTER SYSTEM SET "_use_adaptive_log_file_sync"=FALSE scope=<both/spfile/memory>;