《log file sync》 等待事件问题分析

刘泽宇

1.现象
示例：

数据库的log file sync： Avg wait (ms)达500ms以上，并且CPU 负载相对空闲，IO吞吐量并不大，top event还有其它数据文件相关的I/O class wait event, 并且都是ms级别，这样的负载对于SSD存储通常应该就是在us级。


log file sync理论
官方的definition如下：
When a user session(foreground process) COMMITs (or rolls back), the session’s redo information needs to be flushed to the redo logfile. The user session will post the LGWR to write all redo required from the log buffer to the redo log file. When the LGWR has finished it will post the user session. The user session waits on this wait event while waiting for LGWR to post it back to confirm all redo changes are safely on disk.
  大概的意思指前台进程从提交或回滚事务通知lgwr写redo开始，直到确认redo已成功写入redo logfile为止，期间这个过程就是log file sync等待的过程。
  所以，log file sync是每个事务commit或rollback操作都必经的过程，是否被判为异常等待，主要参考等待时间的长短、等待次数的多少。
  由于需要等待lgwr写redo logfile，因此，log file sync的等待时间涵盖了log file parallel write的时间。

原因分析汇总
1、小事务频繁提交引起：
官方的经验值是：
如果：user calls÷(user commits+user rollbacks) < 30 ，那么可以算事务太过频繁。
以此环境为例：


SQL> select 10316411/(963806+31450) from dual;10316411/(963806+31450)-----------------------             10.3655853 < 30 ，那么可以算事务太过频繁。

2、Bug
commit的过程可以分为两个阶段：
第一阶段为lgwr将redo从log buffer写到redo logfile的过程；
第二阶段lgwr和user session(foreground process) 之间关于写redo logfile结果的信息交互过程。
对于第二阶段，Oracle自从11g R2开始引入了Adaptive Log File Sync的特性，该特性由参数隐含参数“ _use_adaptive_log_file_sync” 控制，决定着前台进程和lgwr之间的交互使用何种方式。
在 Oracle 11201 和 Oracle 11202的版本中，该参数默认设置为 false。从 11.2.0.3 开始默认是 true。
当设置为true启用时，Oracle 可以在两种方法之间自行切换：
Post/wait，传统发布写重做日志完成的方法。
Polling，一种新的方法，其中前台进程会检查 LGWR 是否已写完成。
本环境为11.2.0.3 隐含参数： _use_adaptive_log_file_sync

      INDX NAME                           KSPPDESC                                           KSPPSTVL
---------- ------------------------------ -------------------------------------------------- ----------
      1060 _use_adaptive_log_file_sync    Adaptively switch between post/wait and polling    TRUE
详细可查：Bug 13707904  – LGWR sometimes uses polling,sometimes post/wait.


该BUG可通过设置隐藏参数_use_adaptive_log_file_sync的默认值解决问题。

ALTER SYSTEM SET "_use_adaptive_log_file_sync"= FALSE  scope=both;
同时，此bug开始在oracle 11.2.0.4以及12.1.0.1版本中得到解决。


3、结合：log file parallel write 事件分析
  log file parallel write 事件是LGWR进程专属的等待事件，发生在LGWR将日志缓冲区（log_buffer）中的重做日志信息写入联机重做日志文件组的成员文件，LGWR在该事件上等待该写入过程的完成。该事件的等待表示重做日志所处的磁盘设备缓慢或存在争用。

log file parallel write出现原因
意味着重做日志(redo log)所处的磁盘设备I/O缓慢或存在争用：
磁盘I/O性能比较差
REDO文件的分布导致了I/O争用，例如，同一组的REDO成员文件放在相同的磁盘上。
查看log file parallel write等待事件
select s.event as event_name
,s.time_waited/100 as time_waited
,s.average_wait as averge_wait
from v$system_event s
where s.event in ('log file parallel write','log file sync');

EVENT_NAME                                                       TIME_WAITED AVERGE_WAIT
---------------------------------------------------------------- ----------- -----------
log file parallel write                                           2408236.83         .03
log file sync                                                     2503386.33         .06

汇总：

1.log file sync的平均IO较高，log file parallel write的平均IO较高，可能的IO系统问题；
2.log file sync的平均IO较高，log file parallel write的平均IO低于5ms，远低于log file sync：可以确定IO无问题，有可能是CPU瓶颈。
3.log file sync等待次数很高，log file parallel write的平均IO较低，可能是大量小事务频繁提交导致，这时候通常伴随着CPU使用率较高的现象出现。
4.log file sync和log file parallel write的平均IO都较低，这不一定就代表系统没有问题，有可能是刷redo过程中出现了间隙性的性能问题，IO时间被平均了，这个需要进一步通过OS的信息诊断。