log file sync 事件（轉）

log file sync

 

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寫入到磁盤上。

 

 

 

相關腳本：

--等待時間平均等待時間

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'); 
5. 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>;

 

開啓改參數後，日誌同步機制會在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-21 08: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
4. *** 2015-01-21 08:19:04.077
5. Log file sync switching to polling
6. Current scheduling delay is 1 usec
7. Current approximate redo synch write rate is 1 per sec
8. 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-21 08:46:09.428
2. Log file sync switching to post/wait
3. Current approximate redo synch write rate is 0 per sec
5. *** 2015-01-21 08:47:46.473
6. 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');
3. NAME                                                                  VALUE
4. ---------------------------------------------------------------- ----------
5. 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. /
17. BEGIN_INTERVAL_TIME       INST STAT_NAME                 REDO_SYNCH_POLLS
18. ------------------------- ---- ------------------------- ----------------
19. 06-JAN-15 07.00.02.884 AM    2 redo synch polls                       734
20. 06-JAN-15 08.00.08.425 AM    2 redo synch polls                     23767
21. 06-JAN-15 09.00.13.770 AM    2 redo synch polls                     39827
22. 06-JAN-15 10.00.19.233 AM    2 redo synch polls                     48479
23. 06-JAN-15 11.00.24.431 AM    2 redo synch polls                     41541
24. 06-JAN-15 12.00.29.670 PM    2 redo synch polls                     47566
25. 06-JAN-15 01.00.35.029 PM    2 redo synch polls                     32169
26. 06-JAN-15 02.00.04.159 PM    2 redo synch polls                     37405
27. 06-JAN-15 02.59.04.536 PM    2 redo synch polls                     41469
28. 06-JAN-15 04.00.08.556 PM    2 redo synch polls                     38683
29. 06-JAN-15 05.00.12.523 PM    2 redo synch polls                     51618
30. 06-JAN-15 06.00.16.584 PM    2 redo synch polls                     52511
31. 06-JAN-15 07.00.03.352 PM    2 redo synch polls                     42229
32. 06-JAN-15 08.00.08.663 PM    2 redo synch polls                     35229
33. 06-JAN-15 09.00.13.882 PM    2 redo synch polls                     18499