自適應log file sync影響案例
Oracle最吸引人的地方,就是有些答案,隱藏在種種現象之中,撲朔迷離,朦朦朧朧,就像偵探辦案,首先要有思路,其次要有證據,再者就是紮實的基礎知識,另外就是些運氣。
例如最近碰見了一個案例,一套3節點11.2.0.4 RAC,某應用只用節點1(FAILOVER other nodes),如下是系統負載,某段時間,TPS是554.5,
AWR經常出現log file sync等待事件處於top5/10首位,單次平均等待的時間,11毫秒,
Oracle中有些等待事件,是非常常見的,例如log file sync,當我們從AWR看見他的時候,並不意味著系統有問題,但也不意味著系統沒問題,但從上面資訊看,log file sync一直處於首位,未免讓人生疑。
我們先看下log file sync等待事件的解釋,
當用戶執行commit/rollback指令,redo資訊需要從log buffer重新整理到本地redo log file,進行持久化操作,這就是所謂的“日誌優先寫”,保證資料不丟的前提。日誌重新整理磁碟的操作,就是使用LGWR程序完成的。使用者會話會等待log file sync這個事件,此時,等待LGWR程序返回確認所有redo改變向量已經寫入本地磁碟檔案中。
log file sync等待事件,可以分解為以下步驟,
1. Wakeup LGWR if idle
2. LGWR gathers the redo to be written and issue the I/O
3. Time for the log write I/O to complete
4. LGWR I/O post processing
5. LGWR posting the foreground/user session that the write has completed
6. Foreground/user session wakeup
如果log file sync等待事件時間久,就可以從上面分解步驟,尋找原因。MOS針對這些步驟,提出了一些優化的建議,2和3的資料收集於AWR的redo write time。3對應的就是log file parallel write等待事件。5和6隨著系統負載的增加,可能會比較明顯,這是因為,即使通知了前臺程序,對於作業系統,也需要時間進行排程。
話說回來,通常來講對於log file sync,常見的原因要麼寫日誌慢,要麼commit操作太頻繁。
1. 從上面資訊看,TPS是554.5,並不是非常高,並不能說明commit操作太頻繁。
2. 再來看日誌寫入,log file sync對應前臺程序的等待事件,相應的後臺程序等待事件,就是log file parallel write,如果日誌寫入慢,會體現在log file parallel write單次響應時間慢,但從AWR來看,單次平均等待時間是2毫秒,因此不是因為日誌寫入慢,導致log file sync等待事件,
資料庫版本是11.2.0.4,11g有些新特性值得關注,比如Adaptive Log File Sync,即自適應Log File Sync,有可能是導致log file sync的原因,根據MOS以及一些牛人案例,相關文章的描述,同時也是週五小y瞭解現象,第一時間的反應,什麼是自適應Log File Sync?
首先我們看下,Log File Sync有什麼可以適應。
為了確認commit操作完成與否,LGWR和前臺程序需要通訊,兩種方法,
1. Post/wait
這是之前Oracle版本中傳統的方法。LGWR寫完log buffer的改變向量,就會立刻通知等待commit的程序。優點就是log file sync等待時間很短,相對來說,12c之前由於只有1個LGWR程序,因此LGWR程序負載可能比較重。
2. Polling
使用這種方法,LGWR完成寫入,會進入休眠環節,timeout之後才會檢視log buffer是否寫入。換句話說,LGWR不單獨通知每個等待commit的程序,一定意義上解放了LGWR高負載,隨之帶來的是log file sync時間變久。
Oracle會根據一些內部的演算法,評估post/wait方法效率高,還是polling方法效率高,在高系統負載下,polling可能效率更高,因為post/wait模式下每次重新整理磁碟,均需要和前臺程序通訊。如果系統負載低,post/wait方式效率會高些,相比polling會有更高的響應時間。Oracle依賴於內部統計資料,決定究竟使用何種方法。因為每次post/wait和polling之間的切換,會有些負載產生,因此需要機制,保證這種切換,不要過於頻繁。
按照官方的解釋,log file sync適應的就是post/wait和polling,這兩種日誌寫入通知的機制。
但實際上,對於OLTP應用,polling機制有時是瓶頸,因為他會導致log file sync時間變久,對應的系統commit操作時間變久,影響系統吞吐量。這種現象和本案例相近,再看一些依據。
對於是否採用polling的機制,從v$sysstat檢視可以看出統計資料,若結果為0,則表示未採用,若不為零,則表示採用了。
SQL> select name,value from v$sysstat where name in ('redo synch poll writes','redo synch polls');
AWR中也有這些統計資料,可以看出取樣時間段,日誌寫入通知,採用了polling的機制,從資料看,非常頻繁,
對於wait/post和polling每次切換,在LGWR的trace檔案中均會記錄,而且帶有時間戳,如下就是切換為polling,
*** 2018-01-05 08:21:00.000
kcrfw_update_adaptive_sync_mode: post->poll long#=316 sync#=1719 sync=247657
poll=12382 rw=6191 rw+=13890 ack=0 min_sleep=10023
*** 2018-01-05 08:21:00.001
Log file sync switching to polling
Current scheduling delay is 234 usec
如下則是切換為post/wait,
*** 2018-01-05 08:22:00.000
kcrfw_update_adaptive_sync_mode: poll->post current_sched_delay=0
switch_sched_delay=234 current_sync_count_delta=2275
switch_sync_count_delta=1719
*** 2018-01-05 08:22:00.000Log file sync switching to post/wait
Current approximate redo synch write rate is 758 per sec
對於本文案例,從trace中進行統計,發現log file sync出現明顯的時間段,使用的就是polling機制,即使出現post/wait的記錄,經過1分鐘左右,就切換為了polling機制。
如果需要禁用log file sync自適應,可以設定_use_adaptive_log_file_sync這個隱藏引數為false,這個引數從11gR2版本引入,控制log file sync自適應切換功能,11.2.0.1和11.2.0.2版本中預設值則是false,從11.2.0.3開始預設值改為了true。這是一個動態的引數,可以在系統級進行變更,
ALTER SYSTEM SET "_use_adaptive_log_file_sync"= <FALSE/TRUE> scope=<both/spfile/memory>;
對於本案例來說,首先可以調整的,就是關閉log file sync自適應,而且按照小y所說,這個引數,對於比較繁忙的OLTP系統來說,也是11g下建議預設關閉。
根據MOS介紹,這種log file sync自適應按說會提高日誌檔案同步的整體效能。但同時這一個新特性,會有一些bug產生,MOS建議要麼升級至11.2.0.4/12.1,要麼patch,就是沒說針對OLTP,建議預設關閉,畢竟作為11g新特性,官方就建議關閉,豈不是自己打臉?如下是自適應log file sync,已知和解決的bug,
Document 13707904.8 Bug 13707904 - LGWR sometimes uses polling, sometimes post/wait
Document 13074706.8 Bug 13074706 - Long "log file sync" waits in RAC not correlated with slow writes
Document 25178179.8 Bug 25178179 - Several sessions wait on 'log file sync' in a RAC environment
參考文獻:
Adaptive Log File Sync Optimization (1541136.1)
Troubleshooting: 'Log file sync' Waits (1376916.1)
WAITEVENT: "log file sync" Reference Note (34592.1)
High Waits for 'Log File Sync': Known Issue Checklist for 11.2 (1548261.1)
Adaptive Switching Between Log Write Methods can Cause 'log file sync' Waits (1462942.1)
Bug 13074706 - Long "log file sync" waits in RAC not correlated with slow writes (13074706.8)
Bug 25178179 - Several sessions wait on 'log file sync' in a RAC environment (25178179.8)
"log file parallel write" Reference Note(34583.1)