log file sync

?/*

2015年1月22日

*/


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/O 2.LGWR进程收集redo,然后发给I/O

3. 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"= <FALSE/TRUE>  scope=<both/spfile/memory>;

91pron free videos

开启改参数后,日志同步机制会在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.077

kcrfw_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.077

Log file sync switching to polling

Current scheduling delay is 1 usec

Current approximate redo synch write rate is 1 per sec

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:

*** 2015-01-21 08:46:09.428

Log file sync switching to post/wait

Current approximate redo synch write rate is 0 per sec

*** 2015-01-21 08:47:46.473

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

SQL> select name,value from v$sysstat where name in ('redo sync poll writes','redo synch polls');

NAME                                                                  VALUE

---------------------------------------------------------------- ----------

redo synch polls                                                  325355850


每小时采用poll log file sync方式的次数

col begin_interval_time format a25

col instance_number format 99 heading INST

col stat_name format a25

select snap.BEGIN_INTERVAL_TIME,hist.instance_number , hist.stat_name,hist.redo_synch_polls

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

        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 snap

where redo_synch_polls >0

and hist.snap_id=snap.snap_id

and hist.instance_number=snap.instance_number

order by 1,2

/

BEGIN_INTERVAL_TIME       INST STAT_NAME                 REDO_SYNCH_POLLS

------------------------- ---- ------------------------- ----------------

06-JAN-15 07.00.02.884 AM    2 redo synch polls                       734

06-JAN-15 08.00.08.425 AM    2 redo synch polls                     23767

06-JAN-15 09.00.13.770 AM    2 redo synch polls                     39827

06-JAN-15 10.00.19.233 AM    2 redo synch polls                     48479

06-JAN-15 11.00.24.431 AM    2 redo synch polls                     41541

06-JAN-15 12.00.29.670 PM    2 redo synch polls                     47566

06-JAN-15 01.00.35.029 PM    2 redo synch polls                     32169

06-JAN-15 02.00.04.159 PM    2 redo synch polls                     37405

06-JAN-15 02.59.04.536 PM    2 redo synch polls                     41469

06-JAN-15 04.00.08.556 PM    2 redo synch polls                     38683

06-JAN-15 05.00.12.523 PM    2 redo synch polls                     51618

06-JAN-15 06.00.16.584 PM    2 redo synch polls                     52511

06-JAN-15 07.00.03.352 PM    2 redo synch polls                     42229

06-JAN-15 08.00.08.663 PM    2 redo synch polls                     35229

06-JAN-15 09.00.13.882 PM    2 redo synch polls                     18499