log file sync总结

标签: log file sync | 发表时间:2017-03-09 06:36 | 作者:czmmiao
出处:http://www.iteye.com
log file sync等待时间发生在redo log从log buffer写入到log file期间。
下面对log file sync做个详细的解释。
 
何时发生日志写入:
1.commit或者rollback
2.每3秒
3.log buffer 1/3满或者已经有1M的redo数据。
      更精确的解释:_LOG_IO_SIZE 大小默认是LOG_BUFFER的1/3,当log buffer中redo数据达到_LOG_IO_SIZE 大小时,发生日志写入。
4.DBWR写之前
 
 
_log_io_size隐含参数:
LOG_BUFFER(bytes)写入的数量超过_LOG_IO_SIZE会触发lgwr写日志的条件,缺省值为LOG BUFFER的1/3或1M。
但是这个说法通过查询并不能验证,隐含参数尽量不要修改。
col name for a25
col VALUE for a20
col DESCRIB for a50
SELECT x.ksppinm NAME, y.ksppstvl VALUE, x.ksppdesc describ
FROM SYS.x$ksppi x, SYS.x$ksppcv y
WHERE x.inst_id = USERENV ('Instance')
AND y.inst_id = USERENV ('Instance')
AND x.indx = y.indx
AND x.ksppinm LIKE '_log_io_size';
 
NAME                      VALUE                DESCRIB
------------------------- -------------------- --------------------------------------------------
_log_io_size              0                    automatically initiate log write if this many redo
                                                blocks in buffer
log file sync发生的过程:
此等待事件用户发出提交或回滚声明后,等待提交完成的事件,提交命令会去做日志同步,也就是写日志缓存到日志文件, 在提交命令未完成前,用户将会看见此等待事件.
注意,它专指因提交,回滚而造成的写缓存到日志文件的等待.当发生此等待事件时,有时也会伴随log file parallel write.因为此等待事件将会写日志缓存,如果日志的I/O系统较为缓慢的话,
这必将造成log file parallel write 等待.当发生log file sync等待后,判断是否由于缓慢的日志I/O造成的,可以查看两个等待事件的等待时间,如果比较接近,就证明日志I/O比较缓慢或重做日志过多,这时,造成log file sync的原因是因为log file parallel write,可以参考解决log file parallel write的方法解决问题,
 
**如果log file sync的等待时间很高,而log file parallel write的等待时间并不高,这意味着log file sync的原因并不是缓慢的日志I/O,而是应用程序过多的提交造成。
  当log file sync的等待时间和 log file parallel write等待时间基本相同,说明是IO问题造成的log file sync等待事件。
 
-----
更好理解的解释:
回顾一下单机数据库中的'log file sync' 等待事件,当user session 提交(commit)时,user session会通知LGWR进程将redo buffer中的信息写入到redo log file,当LGWR进程完成写操作后,LGWR再post(通知)user session 写操作已经完成,user session 接收到LGWR的通知后提交操作才完成。因此user session 在没有收到LGWR post(通知)之前一致处于等待状态,具体的等待事件为'log file sync'。
-----
 
引起log file sync的原因:
1.频繁提交或者rollback,检查应用是否有过多的短小的事务,如果有,可以使用批处理来缓解。
2.OS的IO缓慢:解决办法是将日志文件放裸设备上或绑定在RAID 0或RAID 1+0中,而不是绑定在RAID 5中。
3.过大的日志缓冲区(log_buffer )
        过大的log_buffer,允许LGWR变得懒惰,因为log buffer中的数据量无法达不到_LOG_IO_SIZE,导致更多的重做条目堆积在日志缓冲区中。
当事务提交或者3s醒来时,LGWR才会把所有数据都写入到redo log file中。
由于数据很多,LGWR要用更多时间等待redo写完毕。
这种情况,可以调小参数_LOG_IO_SIZE参数,其默认值是LOG_BUFFER的1/3或1MB,取两者之中较小的值。
换句话说,你可以具有较大的日志缓冲区,但较小的_LOG_IO_SIZE将增加后台写入次数,从而减少log file sync的等待时间。
4.CPU负载高。详见下面的描述。
5.RAC私有网络性能差,导致LMS同步commit SCN慢。
 
如何诊断log file sync:
1.AWR:发生log file sync时,先做个snapshot,然后做AWR,AWR时间选择在10-30分钟。
       已发生的log file sync,那么通过AWR依然可以分析,也要保持在10-30分钟。
2.Lgwr trace file(10.2.0.4开始),大于500ms会写入
trace文件中如果有Warning: log write time 1000ms, size 2KB,很有可能IO慢。
3.分析CPU资源使用情况的工具,CPU过于繁忙,lgwr无法及时获取CPU调度,出现log file sync。
vmstat,关注r是否大于CPU核数,大于说明cpu繁忙。
OSW:OSWatcher,同上。
4.Alert:确认log file 15到20分钟切换一次
5.Script to Collect Log File Sync Diagnostic Information (lfsdiag.sql) [Document 1064487.1]
 
 
解决办法:
1.如果确实是因为频繁提交造成的log file sync,那么减少commit。
2.如果确实是因为io引起的,那么解决办法是将日志文件放裸设备上或绑定在RAID 1+0中,而不是放在在RAID 5中(切记,redo log file一定不要放在SSD上!!!)。
3.确保CPU资源充足。CPU资源不足,LGWR通知user session后,user session无法及时获得CPU调度,不能正常工作。
4.是否有些表可以使用nologging,会减少redo产生量
5.检查redo log file足够大,确保redo log file每15到20分钟切换一次。
 
 
更深入分析log file sync:
如果上面的分析没有解决log file sync等待事件,那么需要做下面的分析。
 
The log file sync wait may be broken down into the following components:
log file sync 能拆解为一下步骤:
1. Wakeup LGWR if idle 1.唤醒LGWR进程
2. LGWR gathers the redo to be written and issue the I/O2.LGWR进程收集redo,然后发给I/O
3. Time for the log write I/O to complete3.等待log写入I/O完成
4. LGWR I/O post processing4.LGWR I/O post processing
5. LGWR posting the foreground/user session that the write has completed5.LGWR通知前台/用户回话,redo写入完成
6. Foreground/user session wakeup6.前台/用户会话唤醒
 
Steps 2 and 3 are accumulated in the "redo write time" statistic. (i.e. as found under STATISICS section of Statspack and AWR)
步骤2和3消耗的时间在AWR中的"redo write time"中有所体现。(AWR中 Instance Activity Stats )
 
Step 3 is the "log file parallel write" wait event. (Document:34583.1 "log file parallel write" Reference Note)
步骤3产生"log file parallel write"等待事件。
另外:如果是最大保护模式的DATAGUARD(SYNC传输),这一步骤还包含网络写、RFS/redo写入到备库的standby log file sync的时间。
 
Steps 5 and 6 may become very significant as the system load increases. This is because even after the foreground has been posted it may take a some time for the OS to schedule it to run. May require monitoring from O/S level.
在系统负载高时(尤其是CPU高的情况,看vmstat r值),步骤5和6会变得非常明显。因为,前台收到LGWR写入完成的通知后,操作系统需要消耗一些时间调度Foreground/user session进程唤醒(也就是CPU调度)。需要系统级别监控。
 
 
 
几个技术指标:
log file sync 等待时间小于20ms算正常
log file parallel write 等待时间小于20ms算正常
log file parallel wirte 和log file sync等待时间很接近,说明就是IO问题,因为大部分时间都花在了log写入到磁盘上。
 
 
 
相关脚本:
--等待时间平均等待时间
  1. select EVENT,TOTAL_WAITS,TOTAL_TIMEOUTS,TIME_WAITED,AVERAGE_WAIT
  2.  from   v$system_event 
  3.  where  event in ('log file sync','log file parallel write'); 
  4. select value from v$parameter where name ='log_buffer';
 
---------------新特性:log file sync 两种方式--------------
 
Adaptive Log File Sync 
Adaptive Log File sync was introduced in 11.2. The parameter controlling this feature, _use_adaptive_log_file_sync, is set to false by default in 11.2.0.1 and 11.2.0.2.
 
_use_adaptive_log_file_sync参数在11gR2提出。11.2.0.1和11.2.0.2两个版本该参数默认是false。
从11.2.0.3开始,这个参数默认值是true,也就是开始启用“自适应日志同步机制”。
 
11.2.0.1和11.2.0.2也可以开启改参数
ALTER SYSTEM SET "_use_adaptive_log_file_sync"=  scope=;
 
开启改参数后,日志同步机制会在2种方式中切换。
该参数决定了,foreground/user session 和LGWR进程通过什么方式获知commit操作已完成(也就是redo写log file完成)。
 
Post/wait, traditional method for posting completion of writes to redo log
传统方式,在11.2.0.3之前,user session等待LGWR通知redo写入到log file完毕,被动方式。
优点:post/wait方式,user session几乎能立即发现redo已刷到磁盘。
 
Polling, a new method where the foreground process checks if the LGWR has completed the write.
新方式,主动监测LGWR是否完成写入,主动方式。这种方式比Post/wait方式响应速度慢,但是可以节约CPU资源。
优点:当commit完成后,LGWR会把commit完成的消息通知给很多user session,这个过程消耗大量CPU。
 Polling方式采用朱勇监测LGWR释放写入redo完成,所以释放了LGWR占用的CPU资源。
 
系统负载高(CPU繁忙)采用Polling方式更好。
系统负载低(CPU清闲)采用post/wait方式更好,它能够提供比polling方式更好的响应时间。
ORACLE根据内部统计信息决定采用何种方式。post/wait和polling方式互相切换能引起过热,为了确保安全,切换不要太频繁。
 
LGWR的trace文件记录了switch记录,关键字是 "Log file sync switching to ...":
Switch to polling:
  1. ***2015-01-2108:19:04.077
  2. kcrfw_update_adaptive_sync_mode: post->poll long#=2 sync#=5 sync=62 poll=1056 rw=454 ack=0 min_sleep=1056
  3. ***2015-01-2108:19:04.077
  4. Log file sync switching to polling
  5. Current scheduling delay is 1 usec
  6. Current approximate redo synch write rate is 1 per sec
  7. kcrfw_update_adaptive_sync_mode: poll->post current_sched_delay=0 switch_sched_delay=1 current_sync_count_delta=1 switch_sync_count_delta=5
 
Switch to post/wait:
  1. ***2015-01-2108:46:09.428
  2. Log file sync switching to post/wait
  3. Current approximate redo synch write rate is 0 per sec
  4. ***2015-01-2108:47:46.473
  5. kcrfw_update_adaptive_sync_mode: post->poll long#=2 sync#=11 sync=228 poll=1442 rw=721 ack=0 min_sleep=1056
 
相关脚本:
查询当前log file sync 方式是post-wait还是poll
  1. SQL> select name,value from v$sysstat where name in ('redo sync poll writes','redo synch polls');
  2. NAME                                                                  VALUE
  3. --------------------------------------------------------------------------
  4. redo synch polls                                                  325355850
 
每小时采用poll log file sync方式的次数
  1. col begin_interval_time format a25
  2. col instance_number format 99 heading INST
  3. col stat_name format a25
  4. select snap.BEGIN_INTERVAL_TIME,hist.instance_number , hist.stat_name,hist.redo_synch_polls
  5. from ( select snap_id,instance_number,stat_name,value -lag(value,1,null) over ( order by snap_id,instance_number,stat_name) redo_synch_polls
  6.         from dba_hist_sysstat
  7.         where stat_name='redo synch polls'
  8.         and dbid=(select dbid from v$database)
  9.         and instance_number = nvl('&instance_number',1)) hist,
  10.         dba_hist_snapshot snap
  11. where redo_synch_polls >0
  12. and hist.snap_id=snap.snap_id
  13. and hist.instance_number=snap.instance_number
  14. order by 1,2
  15. /
  16. BEGIN_INTERVAL_TIME       INST STAT_NAME                 REDO_SYNCH_POLLS
  17. ----------------------------------------------------------------------
  18. 06-JAN-1507.00.02.884 AM    2 redo synch polls                       734
  19. 06-JAN-1508.00.08.425 AM    2 redo synch polls                     23767
  20. 06-JAN-1509.00.13.770 AM    2 redo synch polls                     39827
  21. 06-JAN-1510.00.19.233 AM    2 redo synch polls                     48479
  22. 06-JAN-1511.00.24.431 AM    2 redo synch polls                     41541
  23. 06-JAN-1512.00.29.670 PM    2 redo synch polls                     47566
  24. 06-JAN-1501.00.35.029 PM    2 redo synch polls                     32169
  25. 06-JAN-1502.00.04.159 PM    2 redo synch polls                     37405
  26. 06-JAN-1502.59.04.536 PM    2 redo synch polls                     41469
  27. 06-JAN-1504.00.08.556 PM    2 redo synch polls                     38683
  28. 06-JAN-1505.00.12.523 PM    2 redo synch polls                     51618
  29. 06-JAN-1506.00.16.584 PM    2 redo synch polls                     52511
  30. 06-JAN-1507.00.03.352 PM    2 redo synch polls                     42229
  31. 06-JAN-1508.00.08.663 PM    2 redo synch polls                     35229
  32. 06-JAN-1509.00.13.882 PM    2 redo synch polls                     18499

 

 

参考至:http://blog.chinaunix.net/xmlrpc.php?r=blog/article&id=4774739&uid=23284114

如有错误,欢迎指正

邮箱:czmcj@163.com



已有 0 人发表留言,猛击->> 这里<<-参与讨论


ITeye推荐



相关 [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目录.