oracle之等待事件LOG FILE SYNC （awr）优化

log file sycn是ORACLE里最普遍的等待事件之一，一般log file sycn的等待时间都非常短 1-5ms，不会有什么问题，但是一旦出问题，往往都比较难解决。什么时候会产生log file sync等待？
常见有以下几种：
1)commit操作
2)rollback操作
3)DDL操作（DDL操作实施前都会首先进行一次commit）
4)DDL操作导致的数据字典修改所产生的commit
5)某些能递归修改数据字典的操作：比如查询SEQ的next值，可能会导致修改数据字典。一个典型的情况是，SEQ的cache属性设置为nocache，那么会导致每次调用SEQ都要修改数据字典，产生递归的commit。

一个正常的系统里，绝大多数的log file sycn等待都应该是上面描述的1）commit操作造成的log file sycn等待，某些异常的系统，比如频频rollback、seq的cache设置为nocache的系统，也可能会造成比较多的log file sycn等待。

我们要是能知道log file sync包含哪些环节，再有针对性的优化各个环节，就能事半功倍了。
http://www.oracle-developer.net/utilities.php。
方式三：通过lewis的snap_events脚本，获得系统级别等待事件的等待次数、平均等待时间。
rem execute snap_events.start_snap
rem execute snap_events.end_snap

方式四：通过tanel poder的snap脚本采样lgwr后台进程的等待事件分布以及lgwr进程相关的统计信息。

SQL> @snapper out 1 10 1096
-- Session Snapper v2.01 by Tanel Poder ( http://www.tanelpoder.com )
---------------------------------------------------------------------------------
SID, USERNAME , TYPE, STATISTIC , DELTA, HDELTA/SEC, %TIME, GRAPH
---------------------------------------------------------------------------------
1096, (LGWR) , STAT, messages sent , 12 , 12,
1096, (LGWR) , STAT, messages received , 10 , 10,
1096, (LGWR) , STAT, background timeouts , 1 , 1,
1096, (LGWR) , STAT, physical write total IO requests , 40, 40,
1096, (LGWR) , STAT, physical write total multi block request, 38, 38,
1096, (LGWR) , STAT, physical write total bytes, 2884608 , 2.88M,
1096, (LGWR) , STAT, calls to kcmgcs , 20 , 20,
1096, (LGWR) , STAT, redo wastage , 4548 , 4.55k,
1096, (LGWR) , STAT, redo writes , 10 , 10,
1096, (LGWR) , STAT, redo blocks written , 2817 , 2.82k,
1096, (LGWR) , STAT, redo write time , 25 , 25,
1096, (LGWR) , WAIT, LGWR wait on LNS , 1040575 , 1.04s, 104.1%, |@@@@@@@@@@|
1096, (LGWR) , WAIT, log file parallel write , 273837 , 273.84ms, 27.4%,|@@@ |
1096, (LGWR) , WAIT, events in waitclass Other , 1035172 , 1.04s , 103.5%,|@@@@@@@@@@|
-- End of snap 1, end=2010-03-23 12:46:04, seconds=1

复制代码

相关的等待事件
1）log file sync（前台进程的等待事件）
2）log file parallel write（后台进程lgwr的等待事件）
3）log buffer space
lgwr刷新太慢可能会导致这个问题，导致lgwr刷新慢也有几种情况
  1.IO子系统太慢
  2.lgwr不能获得足够的cpu资源
  3.遭遇了大事务(expdp,insert /*+ append */ as ,imp,create as )
也可能是log buffer设置的太小了，不过在现在已经不太可能。默认的尺寸已经很大了。
4）log file single write
这个等待产生的原因是对日志文件头块的读写。一般在如下情况下会产生：
1)日志切换
2)归档

log file sync与buffer busy waits

事物在进行提交的时候，对事物修改的，还在内存里的块做commit cleanout，其实主要就是设置ITL槽位里的commit scn，不会去清楚lb信息。ORACLE在进行commit cleanout期间，会获取相关buffer的buffer pin，而且是排他模式获取，这个pin直到lgwr把日志刷入到磁盘才释放，如果在此期间，有进程对相关的buffer进行select/update/insert就会造成buffer busy waits。因此如果你的系统log file sync指标很高，也可能会导致一定程度的buffer busy waits等待事件。

来自白大师（白鳝）对log file sync等待事件优化的总结，供各位puber们学习参考：

一、　log file sync平均等待事件时间超过7ms，如果等待时间过长，说明log write每次写入的时间过长，如果能够优化redo日志文件存储系统和操作系统，查出变慢的原因。客户检查了存储，没发现故障，于是就不了了之了。在下个月巡检的时候，发现该指标增长到了13ms,再次预警，依然没有发现问题。随后两个月这个指标一直持续恶化，增长到了20多毫秒。由于前面几个月的检查工作没有发现问题，而目前系统也还是很正常的，所以客户也没有再去认真核查。终于有一天，系统突然挂起，５分钟后才恢复正常。后来检查原因，就是log file sync等待导致。根据我的建议，客户从头到尾检查了一遍，最终发现LVM的一条链路存存闪断现象，修复了链路后，一切都恢复正常了。
　　　
　　　通过上面的案例，我们要吸取教训，如果log file sync指标有所恶化，一定要尽快排查问题的根源，如果log file sync的等待时间持续上升，那么系统出现挂起的可能性也在增加。尽快找到问题的原因是势在必行的。

-----------------------------------------------------------------------------

来自盖大师（eygle）对log file sync等待事件优化的总结，供各位puber们学习参考：

http://www.eygle.com/statspack/statspack14-LogFileSync.htm
　当一个用户提交(commits)或者回滚(rollback),session的redo信息需要写出到redo logfile中.
用户进程将通知LGWR执行写出操作,LGWR完成任务以后会通知用户进程.
这个等待事件就是指用户进程等待LGWR的写完成通知.

对于回滚操作，该事件记录从用户发出rollback命令到回滚完成的时间.

如果该等待过多，可能说明LGWR的写出效率低下，或者系统提交过于频繁.
针对该问题，可以关注:
log file parallel write等待事件
user commits,user rollback等统计信息可以用于观察提交或回滚次数

解决方案:
1.提高LGWR性能
尽量使用快速磁盘，不要把redo log file存放在raid 5的磁盘上
2.使用批量提交
3.适当使用NOLOGGING/UNRECOVERABLE等选项

可以通过如下公式计算平均redo写大小：

avg.redo write size = (Redo may be reused.

------------------------------------------------------------------------------------

来自吕大师（vage）对log file sync等待事件优化的总结，供各位puber们学习参考：

1、Log File Sync是从提交开始到提交结束的时间。Log File Parallel Write是LGWR开始写Redo File到Redo File结束的时间。明确了这一点，可以知道，Log file sync 包含了log file parallel write。所以，log file sync等待时间一出，必先看log file parallel write。如果log file sync平均等待时间（也可称为提交响应时间）为20ms，log file parallel write为19ms，那么问题就很明显了，Redo file I/O缓慢，拖慢了提交的过程。

2、 Log File Sync的时间不止log file parallel write。服务器进程开始提交，到通知LGWR写Redo，LGWR写完Redo通知进程提交完毕，来回通知也是要消耗CPU的。除去来回通知外，Commit还有增加SCN等等操作，如果log file sync和log file parallel write差距很大，证明I/O没有问题，但有可能是CPU资源紧张，导致进程和LGWR来回通知或其他的需要CPU的操作，得不到足够的CPU，因而产生延迟。

这种情况下要看一下CPU的占用率、Load，如果Load很高、CPU使用率也很高，哪就是由于CPU导致Log file sync响应时间加长。这种情况下，数据库中观察到这一现象。

5、Log File Sycn和Buffer Busy Waits。
没有直接关系。是其他原因，比如Redo相关的Latch，导致了Log File Sync和Buffer Busy Waits同时出现。此时Log File Sync和Buffer Busy Waits都不是原凶，真正的原凶是Log Buffer访问性能下降。

6、以同步模式向远端DataGuard传送Redo，也会导致Log File Sync。

Redo是Oracle重要的优化对象，DBWR的工作原理我已经破译的差不多了，下一目标就是LGWR，可惜还没来得及搞，以后有时间再为大家详细总结。