log file sync 等待超高一例子

转自：http://www.killdb.com/2014/04/20/log-file-sync-%E7%AD%89%E5%BE%85%E8%B6%85%E9%AB%98%E4%B8%80%E4%BE%8B%E5%AD%90.html

这是3月份某客户的情况，原因是服务器硬件故障后进行更换之后，业务翻译偶尔出现提交缓慢的情况。我们先来看下awr的情况。

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

我们可以看到，该系统的load profile信息其实并不高，每秒才21个transaction。先来看看top5events：

从top 5event，我们可以发现，log file sync的avg wait非常之高，高达124ms。大家应该知道，对于绝大多数情况

下，log file sync的平均等待时间是小于5ms的，这个值有点高的离谱。

我们知道，产生log file sync等待的原因有很多。关于log file sync，tanel Poder大神写过一篇很牛的pdf，大家可以参考下。

这里我主要引用大神的图，来简单描述产生log file sync的原因可能有哪些，首先我们来看下从前端进程提交到最后得到反馈时，以及中间处理的整个流程情况：

 

 

 

从上图中，我们可以清楚的看到整个流程。这里可以进行简单的描述：

1、当user发起一个commit后；

2、前端进程（即Server 进程）会post一个信息给lgwr进程，告诉它，你应该去写redo buffer了。

3、当LGWR进程得到指示后，开始调用操作系统函数进行物理写，在进行物理写的这段时间内，会出现

log file parallel write等待。这里或许有人会有疑问，为什么12c之前只有一个lgwr进程，这里却是parallel

write呢？这里需要说明一下，lgwr进程在将redo buffer中的数据写出到log file文件中时，也是以batch方式

进程的（实际上，dbwN进程也是batch的模式），有相关的隐含参数控制。

4、当LGWR完成wrtie操作之后，LGWR进程会返回一个信息给前端进程（Server进程），告诉它，我已经写完了，

你可以完成提交了。

5.   user 完成commit操作。

这里补充一下，这是由于Oracle 日志写优先的原则，假设在commit之前redo buffer的相关entry信息不立即写到redo

log file中，那么如果数据库出现crash，那么这是会丢数据的。

 

从上面的流程图，我们其实也可以看到，log file sync和log file parallel write可以说是相互关联的。换句话讲，如果log file parallel write的时间很长，那么必然导致log file sync等待时间拉长。

我们假设log file parallel write 等待很高，那么着可能通常是物理磁盘IO的问题，如下：

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

我们从上图可以发行，如果LGWR进程在完成IO操作的过程中时间过长，那么将导致log file parallel write等待升高。

实际上，在整个当用户发出commit到完成commit的过程中，涉及到很多环节，并不是仅仅只有物理IO会影响log file sync/log file parallel write。还有CPU也会影响Log file sync和log file parallel write。我们再来看个图：

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

我们可以看到，上述流程中的4个环节都涉及到CPU的调度，如果在整个事务commit的过程中，系统CPU出现极度紧张，那么这可能会导致LGWR进程无法获得CPU，会进行排队等待，显然，这势必将导致log file sync或log file parallel write等待

的升高。

备注：Oracle中还可以通过隐含参数_high_priority_processes 来控制进程获取CPU的优先级。在一个cpu相对缺乏的系统中，可以通过设置该参数来进行缓解。

最后我们再回到这个案例中来，客户这里的环境，我们是可以排除CPU问题。那么最大的嫌疑可能就是存储本身的问题，导致IO很慢，然而，实际上这也是可以排除的，大家其实应该注意到前面的Top 5 event了，log file parallel write的平均等待

时间并不高，如果是存储IO问题，那么这个event的平均等待时间应该是比较高才对。

 

 

 

 

 

 

我们可以看到log file sync和log file parallel write的waits都是差不多的。但是log file parallel write的avg wait time仅仅只有4ms，这是一个正常的值。也就是说可以我们排除存储IO问题。

那么问题是什么呢 ？我们利用Oracle MOS提供的脚本来查询下log file sync和log file parallel write等待的分布情况：

?

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30

INST_ID EVENT                                    WAIT_TIME_MILLI WAIT_COUNT ---------- ---------------------------------------- --------------- ----------           1 log file sync                                          1     259306           1 log file sync                                          2    2948999           1 log file sync                                          4    1865918           1 log file sync                                          8     173699           1 log file sync                                         16      43194           1 log file sync                                         32       6095           1 log file sync                                         64       1717           1 log file sync                                        128       2458           1 log file sync                                        256       5180           1 log file sync                                        512       9140           1 log file sync                                       1024     558347           1 log file parallel write                                1       5262           1 log file parallel write                                2    4502377           1 log file parallel write                                4    1319211           1 log file parallel write                                8      46055           1 log file parallel write                               16      23694           1 log file parallel write                               32       3149           1 log file parallel write                               64        283           1 log file parallel write                              128        267           1 log file parallel write                              256        157           1 log file parallel write                              512         73           1 log file parallel write                             1024         42           1 log file parallel write                             2048         39           1 log file parallel write                             4096        103           1 log file parallel write                             8192         21           1 log file parallel write                            16384         22           1 log file parallel write                            32768        190           1 log file parallel write                            65536          1

 

大家可以简单的计算一下，其实log file sync和log file parallel write 等待事件，几乎99%左右的平均等待时间都是

小于等于4ms的，这是属于正常的情况；然而有少数的情况其等待时间是很长的，例如log file sync最高的单次等待

时间高达1秒，由于偶尔的等待很高，因此将整个log file sync的平均等待时间拉高了。

到最后，问题就比较清楚了，我认为这是由于主机和存储之间的链路可能出现异常或不稳定导致。临时的解决方法

将redo logfile 挪到本地磁盘，解决了该问题。

后记：经客户后面确认，确实是存储光纤线接口松了。 哈哈