12 / 16 页
完全揭秘log file sync等待事件
认证徽章论坛徽章:1
总结太好了，在Oracle的学习中，这一块儿确实一个疑难点，感谢大师的分享。
论坛徽章:7
本帖最后由 sliangzi 于
10:52 编辑
vage 发表于
“10gR2引入PVRS,避免从PGA到log buffer 的拷贝”
避免不了。很遗憾，Redo还是必须经Log Buffer，才能 ...
当然要经过log buffer,应该能避免从PGA到log buffer吧。
论坛徽章:7
vage 发表于
“10gR2引入PVRS,避免从PGA到log buffer 的拷贝”
避免不了。很遗憾，Redo还是必须经Log Buffer，才能 ...
大师还要多多指点我们啊
认证徽章论坛徽章:19
V哥总结的很彻底，很清晰！
论坛徽章:25
占据一个位置
有时间看看
认证徽章论坛徽章:181
好帖子。收藏下。
认证徽章论坛徽章:488
本帖最后由 guoyJoe 于
17:18 编辑
来自白大师（白鳝）对log file sync等待事件优化的总结，供各位puber们学习参考：
一、 　log file sync平均等待事件时间超过7ms，如果等待时间过长，说明log write每次写入的时间过长，如果能够优化redo日志文件存储，使之存放在更快的磁盘上，就可以减少这个等待事件的单次等待时间。（RAID 5--& RAID 10）
&&　当无法通过优化redo日志的I/O性能来解决问题，或者优化了redo日志的I/O性能后还是无法达到我们的预期，那么该如何处理呢？
&&二、 有经验的DBA可能会建议加大日志缓冲区（log buffer）。提到加大日志缓冲区，可能有些朋友就会感到疑惑，redo日志文件写等待时间长怎么会和日志缓存冲区直接关联起来呢？实际上这个问题解释起来一点也不难，如果数据文件的I/O性能有问题，平均单块读的等待时间偏长，那么通过加大db cache来减少I/O总次数，从而达到优化I/O的效果。加大日志缓存区的原理也是一样的，这样可以使
& & 日志缓存中的存储更多的redo日志数据，从而减少由于redo日志缓存区不足而产生lgwr写操作的数量，使平均每次写入redo日志文件
　　的redo字节数增加，从而减少redo的I/O次数，进而达到优化log file sync等待事件的目的。
　三、如果上述两种方法都不行时，还有一种方法：就是减少提交的次数。如果提交过于频繁，那么无论怎么优化都无法彻底解决问题。
　通过加大一次提交记录的数量，减少提交批次，可以有效地减少log file sync等待时间。采用此方法就意味着需要对应进行较大的调整，甚至要对应用架构做出修改，这种修改的代价将十分巨大。
　四、还有一个方案可以优化log file sync事件，就是把部分经常提交的事务设置为异步提交。
　　异步提交是10g版本引入的新特性，通过设置commit_write参数，可以控制异步提交。
　　commit_write参数默认值是“immediate,wait”
& & 可以设置为“immediate,nowait”来实现异步提交。
& & 采用异步提交的系统需要做一些额外的校验和处理，清理不一致的数据，重新插入刚才由于异步提交而丢失的数据。这就需要在应用层面进行一些特殊处理，建校验机制和错误数据处理机制。我们需要在应用层面进行一些特殊的设置。应该注意的是，那些特别重要的，后续无法重新完全补充的数据不适合使用这种方法
&&log file sync等待事件是十分关键的，我们在数据库的日常维护中应该对此指标建立基线，如果这个指标有异常变化，一定要尽快分析并解决问题。一旦这个指标恶化，可能导致系统性能急剧下降，甚至会导致短暂的挂起。去年，一个客户的系统，平时log file sync的指标是2-3ms。在一次巡检时老白发现该指标增长到了7ms, 当时巡检报告中建议客户关注这个指标，并尽快检查存储系统和操作系统，查出变慢的原因。客户检查了存储，没发现故障，于是就不了了之了。在下个月巡检的时候，发现该指标增长到了13ms,再次预警，依然没有发现问题。随后两个月这个指标一直持续恶化，增长到了20多毫秒。由于前面几个月的检查工作没有发现问题，而目前系统也还是很正常的，所以客户也没有再去认真核查。终于有一天，系统突然挂起，５分钟后才恢复正常。后来检查原因，就是log file sync等待导致。根据我的建议，客户从头到尾检查了一遍，最终发现LVM的一条链路存存闪断现象，修复了链路后，一切都恢复正常了。
　　　通过上面的案例，我们要吸取教训，如果log file sync指标有所恶化，一定要尽快排查问题的根源，如果log file sync的等待时间持续上升，那么系统出现挂起的可能性也在增加。尽快找到问题的原因是势在必行的。
认证徽章论坛徽章:488
本帖最后由 guoyJoe 于
17:17 编辑
来自盖大师（eygle）对log file sync等待事件优化的总结，供各位puber们学习参考：
　当一个用户提交(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 block written/redo writes)*512 bytes
如果系统产生redo很多，而每次写的较少，一般说明LGWR被过于频繁的激活了.
可能导致过多的redo相关latch的竞争,而且Oracle可能无法有效的使用piggyback的功能.
我们从一个statspack中提取一些数据来研究一下这个问题.
我们看到，这里log file sync和db file parallel write等待同时出现了.
显然log file sync在等待db file parallel write的完成.
这里磁盘IO肯定存在了瓶颈，实际用户的redo和数据文件同时存放在Raid的磁盘上，存在性能问题.
由于过渡频繁的提交，LGWR过度频繁的激活，我们看到这里出现了redo writing的latch竞争.
关于redo writing竞争你可以在steve的站点找到详细的介绍:
Oracle Internals Notes
LGWR Latching
When LGWR wakes up, it first takes the redo writing latch to update the SGA variable that shows whether it is active. This prevents other Oracle processes from posting LGWR needlessly. LGWR then takes the redo allocation latch to determine how much redo might be available to write (subject to the release of the redo copy latches). If none, it takes the redo writing latch again to record that it is no longer active, before starting another rdbms ipc message wait.
If there is redo to write, LGWR then inspects the latch recovery areas for the redo copy latches (without taking the latches) to determine whether there are any incomplete copies into the log buffer. For incomplete copies above the sync RBA, LGWR just defers the writing of that block and subsequent log buffer blocks. For incomplete copies below the sync RBA, LGWR sleeps on a LGWR wait for redo copy wait event, and is posted when the required copy latches have been released. The time taken by LGWR to take the redo writing and redo allocation latches and to wait for the redo copy latches is accumulated in the redo writer latching time statistic.
(Prior to release 8i, foreground processes held the redo copy latches more briefly because they did not retain them for the application of the change vectors. Therefore, LGWR would instead attempt to assure itself that there were no ongoing copies into the log buffer by taking all the redo copy latches.)
After each redo write has completed, LGWR takes the redo allocation latch again in order to update the SGA variable containing the base disk block for the log buffer. This effectively frees the log buffer blocks that have just been written, so that they may be reused.
认证徽章论坛徽章:488
本帖最后由 guoyJoe 于
17:17 编辑
来自吕大师（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响应时间加长。这种情况下，数据库通常会有一些并发症，比如Latch/Mutex的竞争会比平常严重些，因为CPU紧张吗，Latch/Mutex竞争一些会加巨的。
3、log file sync和log file parallel write相差很大，但CPU使用率也不高，这种情况比较少见，这就属于疑难杂症范畴了。I/O也很快，CPU也充足，log fie parallel write响应时间很短，但log file sync响应时间确很大。这是最难定位的情况，可以全面对比下Redo相关资料(v$sysstat中的资料）、Redo相关Latch的变化情况。
比如，redo synch time的平均响应时间，不是每次redo synch time都有提交，但每次提交必有redo synch time。如果redo synch time向应快，而log file sync慢，则说明Lgwr和进程的互相通知阶段出了问题。还有redo entries，这个Redo条目数，真正含意是进程向Log Buffer中写Redo的次数。redo log space wait time、redo log space requests资料和Log Buffer Space等待事件也要关注下。Log Buffer的大小通常不会影响Log File Sync，但通过Log Buffer的变化，可以了解Redo量的变化。
关于Log Buffer对Log File Sync的影响，
在新IMU机制下，Redo数据先在共享池中，提交时传到Log Buffer中，如果这时有等待，等待时间是Log Buffer Space。从Log Buffer到磁盘，等待事件才是log file sync。
老机制下也一样，Log Buffer之前的等待是log buffer space，log buffer之后的等待才是log file sync。
4、控制文件I/O有可能影响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，可惜还没来得及搞，以后有时间再为大家详细总结。
认证徽章论坛徽章:488
汇聚于三位国内顶级大师的指点，基本可以结帖了
12 / 16 页
itpub.net All Right Reserved. 北京皓辰网域网络信息技术有限公司版权所有　　　　
　北京市公安局海淀分局网监中心备案编号：　广播电视节目制作经营许可证：编号（京）字第1149号2034人阅读
Mysql_Oracle_Sqlite_MongoDB（54）
log file sync等待时间发生在redo log从log buffer写入到log file期间。下面对log file sync做个详细的解释。何时发生日志写入：1.commit或者rollback2.每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 a25col VALUE for a20col DESCRIB for a50SELECT x.ksppinm NAME, y.ksppstvl VALUE, x.ksppdesc describFROM SYS.x$ksppi x, SYS.x$ksppcv yWHERE x.inst_id = USERENV ('Instance')AND y.inst_id = USERENV ('Instance')AND x.indx = y.indxAND x.ksppinm LIKE '_log_io_size';NAME & & & & & & & & & & &VALUE & & & & & & & &DESCRIB------------------------- -------------------- --------------------------------------------------_log_io_size & & & & & & &0 & & & & & & & & & &automatically initiate log write if this many redo& & & & & & & & & & & & & & & & & & & & & & & & blocks in bufferlog 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 ]
解决办法：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/O
2.LGWR进程收集redo，然后发给I/O3. Time for the log write I/O to complete
3.等待log写入I/O完成4. LGWR I/O post processing
4.LGWR I/O post processing
5. LGWR posting the foreground/user session that the write has completed
5.LGWR通知前台/用户回话，redo写入完成6. Foreground/user session wakeup
6.前台/用户会话唤醒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写入到磁盘上。相关脚本：--等待时间平均等待时间select EVENT,TOTAL_WAITS,TOTAL_TIMEOUTS,TIME_WAITED,AVERAGE_WAIT&from & v$system_event&&where &event in ('log file sync','log file parallel write');&
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:*** 2015-01-21 08:19:04.077kcrfw_update_adaptive_sync_mode: post-&poll long#=2 sync#=5 sync=62 poll=1056 rw=454 ack=0 min_sleep=1056
*** 2015-01-21 08:19:04.077Log file sync switching to pollingCurrent scheduling delay is 1 usecCurrent approximate redo synch write rate is 1 per seckcrfw_update_adaptive_sync_mode: poll-&post current_sched_delay=0 switch_sched_delay=1 current_sync_count_delta=1 switch_sync_count_delta=5Switch to post/wait:*** 2015-01-21 08:46:09.428Log file sync switching to post/waitCurrent approximate redo synch write rate is 0 per sec
*** 2015-01-21 08:47:46.473kcrfw_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还是pollSQL& select name,value from v$sysstat where name in ('redo sync poll writes','redo synch polls');
NAME & & & & & & & & & & & & & & & & & & & & & & & & & & & & & & & & &VALUE---------------------------------------------------------------- ----------redo synch polls & & & & & & & & & & & & & & & & & & & & & & & & &每小时采用poll log file sync方式的次数col begin_interval_time format a25col instance_number format 99 heading INSTcol stat_name format a25select snap.BEGIN_INTERVAL_TIME,hist.instance_number , hist.stat_name,hist.redo_synch_pollsfrom ( select snap_id,instance_number,stat_name,value -lag(value,1,null) over ( order by snap_id,instance_number,stat_name) redo_synch_polls& & & & from dba_hist_sysstat& & & & where stat_name='redo synch polls'& & & & and dbid=(select dbid from v$database)& & & & and instance_number = nvl('&instance_number',1)) hist,& & & & dba_hist_snapshot snapwhere redo_synch_polls &0and hist.snap_id=snap.snap_idand hist.instance_number=snap.instance_numberorder by 1,2/
BEGIN_INTERVAL_TIME & & & INST STAT_NAME & & & & & & & & REDO_SYNCH_POLLS------------------------- ---- ------------------------- ----------------06-JAN-15 07.00.02.884 AM & &2 redo synch polls & & & & & & & & & & & 73406-JAN-15 08.00.08.425 AM & &2 redo synch polls & & & & & & & & & & 2376706-JAN-15 09.00.13.770 AM & &2 redo synch polls & & & & & & & & & & 3982706-JAN-15 10.00.19.233 AM & &2 redo synch polls & & & & & & & & & & 4847906-JAN-15 11.00.24.431 AM & &2 redo synch polls & & & & & & & & & & 4154106-JAN-15 12.00.29.670 PM & &2 redo synch polls & & & & & & & & & & 4756606-JAN-15 01.00.35.029 PM & &2 redo synch polls & & & & & & & & & & 3216906-JAN-15 02.00.04.159 PM & &2 redo synch polls & & & & & & & & & & 3740506-JAN-15 02.59.04.536 PM & &2 redo synch polls & & & & & & & & & & 4146906-JAN-15 04.00.08.556 PM & &2 redo synch polls & & & & & & & & & & 3868306-JAN-15 05.00.12.523 PM & &2 redo synch polls & & & & & & & & & & 5161806-JAN-15 06.00.16.584 PM & &2 redo synch polls & & & & & & & & & & 5251106-JAN-15 07.00.03.352 PM & &2 redo synch polls & & & & & & & & & & 4222906-JAN-15 08.00.08.663 PM & &2 redo synch polls & & & & & & & & & & 3522906-JAN-15 09.00.13.882 PM & &2 redo synch polls & & & & & & & & & & 18499
参考知识库
* 以上用户言论只代表其个人观点，不代表CSDN网站的观点或立场
访问：483877次
积分：8825
积分：8825
排名：第1521名
原创：367篇
转载：95篇
评论：101条
(2)(5)(1)(1)(2)(1)(2)(1)(2)(2)(4)(2)(2)(6)(4)(5)(1)(11)(5)(5)(15)(11)(3)(17)(2)(1)(11)(4)(5)(9)(9)(6)(24)(150)(41)(23)(1)(37)(29)(3)