log file sync等待超高一例

标签: log file sync | 发表时间:2014-04-20 12:47 | 作者:lovewifelovelife
出处:http://blog.csdn.net

这是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 挪到本地磁盘,解决了该问题。

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

作者:lovewifelovelife 发表于2014-4-20 12:47:05 原文链接
阅读:97 评论:0 查看评论

相关 [log file sync] 推荐:

log file sync总结

- - 数据库 - ITeye博客
log file sync等待时间发生在redo log从log buffer写入到log file期间. 下面对log file sync做个详细的解释. 1.commit或者rollback. 3.log buffer 1/3满或者已经有1M的redo数据.       更精确的解释:_LOG_IO_SIZE 大小默认是LOG_BUFFER的1/3,当log buffer中redo数据达到_LOG_IO_SIZE 大小时,发生日志写入.

log file sync等待超高一例

- - CSDN博客数据库推荐文章
这是3月份某客户的情况,原因是服务器硬件故障后进行更换之后,业务翻译偶尔出现提交缓慢的情况. 我们可以看到,该系统的load profile信息其实并不高,每秒才21个transaction. 先来看看top5events:. 从top 5event,我们可以发现,log file sync的avg wait非常之高,高达124ms.

Oracle Tuning Log File Sync 等待事件的几种策略

- - CSDN博客数据库推荐文章
    在一个频繁 commit/rollback 或磁盘 I/O 有问题、大量物理读写争用.    那么、我们便会经常瞧见 LOG FILE SYNC 等待事件出现在 TOP EVENTS 中.    评估 LOG FILE SYNC等待事件的指标是平均等待时间、以及 AWR 后续的 WAIT EVENT HISTOGRAM.

Log调试

- - ITeye博客
在开发中我们一定不能避免使用Log类,但是这个类存在一个问题就是,当你在程序中使用了大量的Log,那么在程序开发完毕的时候,这将是一个问题,因为,你需要将所有的Log记录注释掉(当然,你不注释也是可以的). 我们可以写一个类,将Log类包装起来,使用一个boolean来控制所有的Log记录的显示. public static final boolean isDebug = true;//这里控制所有Log的显示情况.

Oracle online redo log 扫盲

- - CSDN博客数据库推荐文章
Oracle 的日志分为:ONLINE REDO LOG 和 archived log. 一个数据库至少要有2组 redo log,每组 redo log 至少要有一个 member(出于安全考虑,建议每组 redo log 至少有 2 个多元化的 redo log member). redo log 循环使用,当一组日志写满后,就会切换到下一组日志.

oracle的控制文件(control file)

- - CSDN博客数据库推荐文章
1: 对oracle database  files进行说明. 2: oracle doc 对 control file的定义. 3:查找oracle数据文件的三种方式. 控制文件是一个小小的二进制文件,是oracle数据库的一部分,这个控制文件是用于记录数据库的状态和物理结构. 每个数据库必须要至少一个控制文件,但是强烈的建议超过一个控制文件,每个控制文件的备份应该放在不同的磁盘上.

hbase权威指南: store file合并(compaction)

- - CSDN博客推荐文章
          hbase为了防止小文件(被刷到磁盘的menstore)过多,以保证保证查询效率,hbase需要在必要的时候将这些小的store file合并成相对较大的store file,这个过程就称之为compaction. 在hbase中,主要存在两种类型的compaction:minor  compaction和major compaction.

db file sequential read等待事件总结

- - CSDN博客数据库推荐文章
该等待事件的参数:file#,first block#,and block count(一般是1)可以从dba_extents去确定访问的段,属于I/O类的等待. The Oracle process wants a block that is currently not in the SGA, and it is waiting for the database block to be read into the SGA from disk..

静态cache之log共现词分析

- - 搜索技术博客-淘宝
搜索引擎的log数据可以用于query理解、user理解、doc理解和ranking. 我们运行共现词分析,挖掘出引擎的query log里面共现的词,离线建静态cache,用于提升引擎的性能. 分析query log里query的平均的term数,值为5. 我们对query log依次进行一至四元共现词分析,高于四元的我们推荐用fullcache解决,而且高元的离线计算成本也太高.

[转]用mysqldumpslow分析mysql的slow query log

- - 小彰
mysql有一个功能就是可以log下来运行的比较慢的sql语句,默认是没有这个log的,为了开启这个功能,要修改my.cnf或者在mysql启动的时候加入一些参数. 如果在my.cnf里面修改,需增加如下几行. long_query_time 是指执行超过多久的sql会被log下来,这里是1秒. log-slow-queries 设置把日志写在那里,可以为空,系统会给一个缺省的文件 host_name-slow.log,我生成的log就在mysql的data目录.