log file sync等待超高一例

这是3月份某客户的情况，原因是server硬件故障后进行更换之后，业务翻译偶尔出现提交缓慢的情况。我们先来看下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 挪到本地磁盘，攻克了该问题。

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