小麦苗的今日寄语
朋友不是嘴上说，而是心里有；
感情不是一人惜，而是两相守 。
能够用时间陪你的人，才是爱人；
愿意用深情等你的人，才是朋友。
今天给大家分享的是【等待事件】日志类 等待事件（4.2）--log file sync（日志文件同步）
等待事件历史文章~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
● 【故障处理】队列等待之enq: TX - row lock contention
● 【故障处理】队列等待之TX - allocate ITL entry案例
● 【故障处理】队列等待之enq: US - contention案例
● 【故障处理】队列等待之TX - allocate ITL entry引起的死锁处理（上）
● 【故障处理】队列等待之TX - allocate ITL entry引起的死锁处理（下）--ITL死锁模拟
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
●【等待事件】User I/O类 等待事件（2.1）--db file sequential read（数据文件顺序读）
●【等待事件】User I/O类 等待事件（2.2）--db file scattered read（数据文件离散读）
●【等待事件】User I/O类 等待事件（2.3）--db file parallel read
● 【等待事件】User I/O类 等待事件（2.4）--db file single write
● 【等待事件】User I/O类 等待事件（2.5）--direct path read（直接路径读、DPR）
● 【等待事件】User I/O类 等待事件（2.6）--direct path write（直接路径写、DRW）
● 【等待事件】User I/O类 等待事件（2.7）--direct path read/write temp
● 【等待事件】User I/O类 等待事件（2.8）--read by other session
● 【等待事件】User I/O类 等待事件（2.9）--local write wait
● 【等待事件】User I/O类 等待事件（2.10）--所有User I/O类 等待事件总结
● 【等待事件】System I/O类 等待事件（3.1）--db file parallel write
● 【等待事件】System I/O类 等待事件（3.2）--control file parallel write
● 【等待事件】System I/O类 等待事件（3.3）--control file sequential read
● 【等待事件】System I/O类 等待事件（3.4）--control file single write
● 【等待事件】日志类 等待事件（4.1）--log file switch（日志文件切换）
【等待事件】日志类 等待事件（4.2）--log file sync（日志文件同步）
SELECT * FROM V$EVENT_NAME A WHERE A.NAME LIke 'log file sync';
在V$SESSION_WAIT这个视图里面，这个等待事件有三个参数P1、P2、P3，其中P1为buffer#代表在日志缓冲区中需要被写入到重做日志文件中的缓存的数量，即redo buffer 中需要被写入到磁盘中的buffer。写入的同时会确认事务是否已经被提交，并且保留提交信息到实例意外中断之前，因此必须等待LGWR将P1数量的缓存写入重做日志文件为止。P2、P3属于无用的参数。
更多请参考metalink：1626301.1，地址：http://blog.itpub.net/26736162/viewspace-2124856/
英文版：Troubleshooting: 'Log file sync' Waits (文档 ID 1376916.1)
此等待事件用户发出提交或回滚声明后,等待提交完成的事件,提交命令会去做日志同步,也就是写日志缓存到日志文件， 在提交命令未完成前,用户将会看见此等待事件,注意,它专指因提交,回滚而造成的写缓存到日志文件的等待.当发生此等待事件时,有时也会伴随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,而是应用程序过多的提交造成的.
当一个用户提交或回滚数据时，LGWR将会话期的重做由日志缓冲区写入到重做日志中，LGWR完成任务以后会通知用户进程。日志文件同步过程（Log File Sync）必须等待这一过程成功完成。对于回滚操作，该事件记录从用户发出Rollback命令道回滚完成的时间。如果该等待过多，可能说明LGWR的写出效率低下，或者系统提交过于频繁。针对该问题，可以通过log file parallel write等待事件或User Commits、User Rollback等统计信息来观察提交或回滚次数。
这是一个用户会话行为导致的等待事件，当一个会话发出一个commit命令时，LGWR进程会将这个事务产生的redo log从log buffer里面写到磁盘上，以确保用户提交的信息被安全地记录到数据库中。
当一个用户会话提交，会话的重做信息需要从内存刷新到重做日志文件，使其永久化。
这个等待事件是指等待Oracle的前台的COMMIT和ROLLBACK操作进程完成，有时候这个等待事件也会包括等待LGWR进程把一个会话事务的日志记录信息从日志缓冲区中写入到磁盘上的重做日志文件中。因此，当前台进程在等待这个事件的时候，LGWR进程同时也在等待事件log file parallel write。理解什么造成这个等待事件的关键在于对比这个等待事件和log file parallel write等待事件的平均等待时间：如果它们的等待时间差不多，那么就是重做日志文件的I/O引起了这个等待事件，则需要调整重做日志文件的I/O，这个在之后会有详细的讲述。如果log file parallel write等待事件的平均等待时间明显小于log file sync等待事件的等待时间，那么就是一些其他的写日志的机制在COMMIT和ROLLBACK操作的时候引起了等待，而不是I/O引起的等待，例如重做日志文件的latch的竞争，会伴随着出现latch free或者LGWR wait for redo copy等待事件。
在提交时，用户会话会通知 LGWR 把日志缓冲区中的信息写到重做日志文件（当前所有未被写入磁盘的 redo 信息，包括本次会话的 redo 信息）。当 LGWR 完成写操作后，它会通知用户会话。当等待 LGWR 通知确认所有 redo 已经安全的保存到磁盘的过程时，用户会话会等待'log file sync'。
用户会话显示等待'log file sync'，是用户会话通知 LGWR 和 LGWR 通知用户的写操作完成之间的时间。
需要注意的是，如果已有一个正在进行的同步，其他需要提交的会话（为了保存日志信息）也需等待 LGWR，进而也将等待'log file sync'？
当系统中出现大量的log file sync等待事件时，应该检查数据库中是否有用户在做频繁的提交操作。这种等待事件通常发生在OLTP系统上。 OLTP 系统中存在很多小的事务，如果这些事务频繁被提交，可能引起大量的log file sync的等待事件。
如果这个等待事件在整个等待时间中占了比较大的比重，可以从以下几个方面来调整这个等待事件：
1).调整LGWR进程使其具有更好的磁盘I/O吞吐量，尽量使用快速磁盘，不要把redo log file存放在RAID5的磁盘上；RAID5 对于频繁写入得系统会带来较大的性能损失，可以考虑使用文件系统直接输入/输出，或者使用裸设备(raw device)，这样可以获得写入的性能提高。
2). 使用批量提交 如果存在很多执行时间很短的事务，可以考虑将这些事务集合成一个批处理事务以减少提交的次数，因为每次提交都需要确认相关的日志写入重做日志文件，因此使用批处理事务来减少提交的次数是一种非常行之有效的减少I/O的方法。
3). 适当使用NOLOGGING/UNRECOVERABLE等选项，查看是否一些操作可以安全的使用NOLOGGING或者UNRECOVERABLE选项，这样可以减少日志的产生。
用户应该搜集那些信息，来初步分析'log file sync'等待事件？
初步分析等待'log file sync'，下面的信息是有帮助的：
l 没有'log file sync'等待的类似时间的 AWR 报告，作为用于比较的性能基线
l 'log file sync'等待发生期间的 AWR 报告 注：2 个报告应在 10-30 分钟之间。
l LGWR 日志文件 当'log file parallel wait'高的时候，LGWR 日志文件将会显示警告信息
什么原因造成了很高的’log file sync’等待？
‘log file sync’可以在用户会话通知 LGWR 写日志，和 LGWR 写完日志后通知用户会话，及用户会话被唤醒间的任何一个点发生。
更多详情，请参照文档:
Document:34592.1 WAITEVENT: "log file sync"
其中的最常见的原因：
Ø 影响 LGWR 的 I/O 性能问题
Ø 过多的应用程序 commit
这些原因以及如何解决它们详情概述如下：
影响 LGWR 的 IO 性能问题
我们在这里回答的主要问题是“是否 LGWR 写入磁盘慢？”,下面的步骤可以帮助确定是否是这个导致的。
比较'log file sync'和'log file parallel write'的平均等待时间。
等待事件'log file parallel write'表示 LGWR 正在等待写 redo 操作。该事件的持续时间就是等待 IO 操作部分的时间。关于'log file parallel write'的更多信息，请参阅:
Document:34583.1 WAITEVENT: "log file parallel write" Reference Note
结合事件“log file sync”看同步操作消耗在 IO 的时间，由此推断，有多少处理时间消耗在 CPU 上。 
上面的例子显示了'log file sync' 和 'log file parallel write' 都有很高的等待时间
如果'log file sync'的时间消耗在'log file parallel write'上的比例高，那么大部分的等待时间是由于 IO（等待 redo 写入）。应该检查 LGWR 在 IO 方面的性能。作为一个经验法则，'log file parallel write'平均时间超过 20 毫秒, 意味着 IO子系统有问题。
建议：
1. 与系统管理员一起检查重做日志所在的文件系统的位置，以提高 IO 性能。
2. 不要把重做日志放在需要额外计算的RAID上，比如 RAID-5或者RAID-6
3. 不要把重做日志放在 Solid State Disk (SSD)
虽然通常情况下，SSD 写入性能好于平均水平，他们可能会遇到写峰值,从而导致大量的增加'log file sync'等待(关于这一点您需要详尽的测试，因为我们也碰到一些SSD的性能可以接受的系统)
(Engineered Systems (Exadata, SuperCluster 和 Oracle Database Appliance) 除外，因为在这些系统上已经为使用SSD来存放重做日志而做了额外的优化)
4. 监控其他可能需要写到相同路径的进程，确保该磁盘具有足够的带宽，足以应付所要求的容量。如果不能满足,移动这些进程或 redo。
5. 确保 LOG_BUFFER 不要太大，一个非常大的 log_buffer 的不利影响就是刷新需要更长的等待时间。当缓冲区满了的时候，它必须将所有数据写入到重做日志文件。LGWR 将一直等待,直到最后的 I/O 完成。
间歇性物理IO缓慢对 'log file sync' 等待事件的影响：
LGWR倾向于做很多小的IO操作，而不是大块的IO操作。大部分的磁盘配置并不能在这种场景下很好的工作，可能会发生间歇性物理IO缓慢。但是从平均等待时间来看，IO等待的时间并不长，磁盘设备提供商据此断定没有磁盘问题。 因为系统里还有其它的IO操作，所有这些正常的IO操作的等待时间很短，所有这些IO操作平均起来的等待时间并不长，这就掩盖了间歇性物理IO缓慢的问题。 但是间歇性物理IO缓慢的问题会造成很高的'log file sync', 虽然平均的'log file parallel write'是处于正常性能的范围
如果你发现系统的'log file sync'很高，但是'log file parallel write'是处于正常的范围，那么这可能是由于间歇性物理IO缓慢导致的。你需要使用一些像OSWatcher一样的工具(参照 Document 301137.1)来确定是否系统中存在间歇性物理IO缓慢。如果可以确定存在间歇性物理IO缓慢, 那么你需要与磁盘提供商一起来解决这个问题。
检查 LGWR trace
尽管'log file parallel write'的平均等待时间可能在一个合理的区间范围内，在峰值时刻写操作时间还是可能会很长进而影响’log file sync’的等待时间。从10.2.0.4 开始如果写操作超过 500 毫秒我们会在 LGWR 的 trace 中写警告信息。这个阀值很高所以就算没有警告也不代表没有问题。警告信息如下：
*** 2011-10-26 10:14:41.718
Warning: log write elapsed time 21130ms, size 1KB
(set event 10468 level 4 to disable this warning)
*** 2011-10-26 10:14:42.929
Warning: log write elapsed time 4916ms, size 1KB
(set event 10468 level 4 to disable this warning)
注意：上面的峰值如果时间间隔的很远,可能不会对'log file parallel wait'有大的影响。 但是，如果有 100 个会话等待'log file parallel wait'完成，'log file sync'总等待可能就会很高，因为等待时间将被乘以会话的个数 100。因此，值得探讨日志写 IO 高峰的原因。
请参阅：
Document:601316.1 LGWR Is Generating Trace file with "Warning: Log Write Time 540ms, Size 5444kb" In 10.2.0.4 Database
建议：
与系统管理员一起检查其他正在发生的可能会导致 LGWR 写磁盘峰值的操作
当 LGWR 进程慢的时候，对其进行 Truss 操作会帮助确定时间消耗在什么地方
注意：这些警告信息对于预防潜在问题的发生很有帮助。就算平均等待时间没问题，通过找到 I/O 性能峰值点，DBA 可以知道 LGWR 会间歇性的遇到性能问题，进而在它引发更大问题前将其解决。
检查在线重做日志是否足够大
每次重做日志切换到下一个日志时，会执行'log file sync'操作，以确保下一个日志开始之前信息都写完。 标准建议是日志切换最多 15 至 20 分钟一次。 如果切换比这更频繁，那么将发生更多的'log file sync'操作，意味着更多的会话等待。
检查 alert.log 日志文件切换的时间
Thu Jun 02 14:57:01 2011
Thread 1 advanced to log sequence 2501 (LGWR switch)
Current log# 5 seq# 2501 mem# 0: /opt/oracle/oradata/orcl/redo05a.log
Current log# 5 seq# 2501 mem# 1: /opt/oracle/logs/orcl/redo05b.log
Thu Nov 03 14:59:12 2011
Thread 1 advanced to log sequence 2502 (LGWR switch)
Current log# 6 seq# 2502 mem# 0: /opt/oracle/oradata/orcl/redo06a.log
Current log# 6 seq# 2502 mem# 1: /opt/oracle/logs/orcl/redo06b.log
Thu Nov 03 15:03:01 2011
Thread 1 advanced to log sequence 2503 (LGWR switch)
Current log# 4 seq# 2503 mem# 0: /opt/oracle/oradata/orcl/redo04a.log
Current log# 4 seq# 2503 mem# 1: /opt/oracle/logs/orcl/redo04b.log
在上面的例子中，我们看到每 2 到 4 分钟进行日志切换，这比建议值的5倍还高。
您也可以检查 AWR 报告日志切换的平均时间
在上面的例子中基于 AWR 中的信息，每小时有 29.98 次重做日志切换：每 2 分钟切换一次。这个比每 15-20 分钟切换一次的建议值要高,并将影响前台进程需要等待'log file sync'完成的时间，因为发起同步操作的开销比必要的多。
建议：增加redo logs的大小
Document:602066.1 How To Maintain and/or Add Redo Logs
Document:779306.1 How To Add/Increase The Size Of Redo Log Files In Rac Environment?
应用程序提交过多
在这种情况下，要回答的问题是“是否应用程序 commit 过于频繁？ ”。
如果是，那么过多的 commit 活动可能会导致性能问题，因为把 redo 从日志缓冲区刷新到重做日志可能会导致等待'log file sync'。
如果’log file sync’的平均等待时间比’log file parallel write’高很多，这意味着大部分时间等待不是由于等待 redo 的写入，因而问题的原因不是 IO 慢导致。 剩余时间是 CPU 活动，而且是过多的 commit 导致的最常见的竞争。
此外，如果'log file sync'的平均等待时间低，但等待次数高，那么应用程序可能 commit 过于频繁。
比较 user commit/rollback 同 user calls 比值的平均值：
在 AWR 或 Statspack 报告中，如果每次 commit/rollback 的平均 user calls（"user calls/(user commits+user rollbacks)"） 小于 30， 表明 commit 过于频繁
在上面的例子中，我们看到，平均每 5.76 次 user calls 就会有一次 commit, 大约高出建议值 5 倍。基于经验，我们期望 user calls/user commit 至少是 25。当然，这取决于应用程序。
建议：
如果有很多短事务，看是否可能把这些事务组合在一起，从而减少 commit 操作。 因为每一个 commit 都必须收到相关 REDO 已写到磁盘上的确认，额外的 commit 会显著的增加开销。虽然 Oracle 可以将某些 commit 组合在一起，通过事务的批处理来减少commit的总体数量还是可以带来非常有益的效果。
看看是否有操作可以使用 COMMIT NOWAIT 选项 （务必在使用前应明白语义）。
看看是否有操作可以安全地使用 NOLOGGING/ UNRECOVERABLE 选项完成。
其他可能相关的等待事件：
检查 AWR 报告，看是否有跟 LGWR 相关的,显示占用了显著数量时间的其他事件,因为这可能会给出导致这个问题的一个线索。前台和后台事件都应该进行检查。
例如下面的 AWR 显示某些其他前台和后台等待事件等待高，意味着传输重做日志到远程位置的问题，这可能会导致 fore gorund 进程等待"log file sync"。
Adaptive Log File Sync
11.2 中引入了 Adaptive Log File sync，由参数 _use_adaptive_log_file_sync 控制，在 11.2.0.1 和 11.2.0.2 默认设置为 false。
从 11.2.0.3 开始默认是 true。 当启用时，Oracle 可以在两种方法之间切换：
Post/wait，传统发布写重做日志完成的方法
Polling，一种新的方法，其中前台进程会检查 LGWR 是否已写完成。
更多关于这个特性的信息，请参阅:
Document 1541136.1 Waits for "log file sync" with Adaptive Polling vs Post/Wait Choice Enabled
Redo Synch Time Overhead：
统计值'redo synch time overhead'在11.2.0.4和12c被引入，记录了理想的log file sync时间以及真正的log file sync时间的差值。
如果这个差值很小，说明log file sync等待次数可能是log file parallel write等待之外的原因导致的
当一个用户提交或回滚数据时，LGWR将会话期的重做由Log Buffer写入到重做日志中，
LGWR完成任务以后会通知用户进程。日志文件同步等待（Log File Sync）就是指进程等待
LGWR写完成这个过程；对于回滚操作，该事件记录从用户发出rollback命令到回滚完成的时
间。
如果该等待过多，可能说明LGWR的写出效率低下，或者系统ᨀ交过于频繁。针对该问
题，可以关注log file parallel write等待事件，或者通过user commits,user rollback等统计信息
观察ᨀ交或回滚次数。
可能的解决方案主要有：
l ᨀ高LGWR性能，尽量使用快速磁盘，不要把redo log file存放在RAID5的磁盘上；
l 使用批量ᨀ交；
l 适当使用NOLOGGING/UNRECOVERABLE等选项。
可以通过如下公式计算平均Redo写大小：
avg.redo write size = (Redo block written/redo writes)*512 bytes
如果系统产生Redo很多，而每次写的较少，一般说明LGWR被过于频繁地激活了。可
能导致过多的Redo相关Latch的竞争，而且Oracle可能无法有效地使用piggyback的功能。
从一个Statspack报告中ᨀ取一些数据来研究一下这个问题。
Report概要信息如下：
DB Name DB Id Instance Inst Num Release OPS Host
------------ ----------- ------------ -------- ----------- --- ------------
DB 1222010599 oracle 1 9.1.7.4.5 NO sun
Snap Id Snap Time Sessions
------- ------------------ --------
Begin Snap: 3473 13-Oct-04 13:43:00 540
End Snap: 3475 13-Oct-04 14:07:28 540
Elapsed: 24.47 (mins)
Cache Sizes
~~~~~~~~~~~
db_block_buffers: 102400 log_buffer: 20971520
db_block_size: 8192 shared_pool_size: 600M
Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 28,459.11 2,852.03
等待事件如下：
Event Waits Timeouts Time (cs) (ms) /txn
---------------------------- ------------ ---------- ----------- ------ ------
log file sync 14,466 2 4,150 3 1.0
db file sequential read 17,202 0 2,869 2 1.2
latch free 24,841 13,489 2,072 1 1.7
direct path write 121 0 1,455 120 0.0
db file parallel write 1,314 0 1,383 11 0.1
log file sequential read 1,540 0 63 0 0.1
log file switch completion 1 0 3 30 0.0
refresh controlfile command 23 0 1 0 0.0
LGWR wait for redo copy 46 0 0 0 0.0
log file single write 4 0 0 0 0.0
注意以上输出信息，这里log file sync和db file parallel write等等待事件同时出现，那么
可能的一个原因是I/O竞争导致了性能问题，实际用户环境正是日志文件和数据文件同时存放
在RAID5的磁盘上，存在性能问题需要调整。
统计信息如下：
Statistic Total per Second per Trans
--------------------------------- ---------------- ------------ ------------
……
redo blocks written 93,853 63.9 6.4
redo buffer allocation retries 1 0.0 0.0
redo entries 135,837 92.5 9.3
redo log space requests 1 0.0 0.0
redo log space wait time 3 0.0 0.0
redo ordering marks 0 0.0 0.0
redo size 41,776,508 28,459.1 2,852.0
redo synch time 4,174 2.8 0.3
redo synch writes 14,198 9.7 1.0
redo wastage 4,769,200 3,249.8 325.6
redo write time 3,698 2.5 0.3
redo writer latching time 0 0.0 0.0
redo writes 14,572 9.9 1.0
……
sorts (disk) 4 0.0 0.0
sorts (memory) 179,856 122.5 12.3
sorts (rows) 2,750,980 1,874.0 187.8
……
transaction rollbacks 36 0.0 0.0
transaction tables consistent rea 0 0.0 0.0
transaction tables consistent rea 0 0.0 0.0
user calls 1,390,718 947.4 94.9
user commits 14,136 9.6 1.0
user rollbacks 512 0.4 0.0
write clones created in backgroun 0 0.0 0.0
write clones created in foregroun 11 0.0 0.0
-------------------------------------------------------------
根据统计信息可以计算平均日志写大小：
avg.redo write size = (Redo block written/redo writes)*512 bytes
= ( 93,853 / 14,572 )*512
= 3KB
这个平均值过小了，说明系统的ᨀ交过于频繁。从以上的统计信息中，可以看到平均每
秒数据库的ᨀ交数量是9.6次。如果可能，在设计应用时应该选择合适的ᨀ交批量，从而ᨀ高
数据库的效率。
Latch Sleep breakdown for DB: DPSHDB Instance: dpshdb Snaps: 3473 -3475
-> ordered by misses desc
Get Spin &
Latch Name Requests Misses Sleeps Sleeps 1->4
-------------------------- -------------- ----------- ----------- ------------
row cache objects 12,257,850 113,299 64 113235/64/0/0/0
shared pool 3,690,715 60,279 15,857 52484/588/6546/661/0
library cache 4,912,465 29,454 8,876 23823/2682/2733/216/0
cache buffers chains 10,314,526 2,856 33 2823/33/0/0/0
redo writing 76,550 937 1 936/1/0/0/0
session idle bit 2,871,949 225 1 224/1/0/0/0
messages 107,950 159 2 157/2/0/0/0
session allocation 184,386 44 6 38/6/0/0/0
checkpoint queue latch 96,583 1 1 0/1/0/0/0
-------------------------------------------------------------
由于过度频繁的ᨀ交，LGWR过度频繁的激活，看到这里出现了redo writing的latch 竞
争。
以下是一则ASH报告中显示的Log File Sync等待信息，注意到其Parameter 1是Buffer#，
Parameter 2代表Sync SCN，也就是同步的SCN。Log File Sync以SCN为节点，以Buffer号
为起始，不断将Log Buffer的内容写出到日志文件上来：
● 本文作者：小麦苗，只专注于数据库的技术，更注重技术的运用
● 于 2016-09-08 09:00~2016-09-08 19:00 在泰兴公寓完成
● 【版权所有，文章允许转载，但须以链接方式注明源地址，否则追究法律责任】
|
|
本文分享自微信公众号 - DB宝（lhrdba）。
如有侵权，请删除。
