953
Oracle高並發係列2：事務日誌寫入引發的Redo log風波
作者介紹
王鵬衝，平安科技數據庫技術專家，浸淫數據庫行業十多年，對Oracle數據庫有濃厚興趣，也對MySQL、MongoDB、Redis等數據庫有一定架構和運維經驗，目前正沉迷在PostgreSQL數據庫與Oracle數據庫的PK之中，重點在關係型數據庫的分布式架構研究。
引言
關係型數據庫強調事務的ACID特性，對於事務的持久性，主流的關係型數據庫都是通過寫事務日誌來實現的。寫數據是隨機IO，寫日誌是順序IO，常規的機械磁盤，隨機IO比順序IO要昂貴很多。所以雖然寫日誌同樣要刷到磁盤才能算事務提交完成（Oracle、PG、MySQL寫日誌的控製也各自有不同的機製，後續有空再對比總結），但是由於寫日誌的速率高於寫數據，所以每次會話commit時將事務日誌同步刷入online redo logfile，比將數據同步刷入datafile要更加高效。
Oracle數據庫一樣是先寫日誌後寫數據的設計，那麼問題就來了，當基於Oracle數據庫的應用係統，在業務舉辦搶售類促銷活動等高並發的場景下，短時間內有大量的事務日誌需要寫入online reo log的時候，日誌寫的效率就會有一定問題，這個時候Oracle數據庫的log file sync會成為主要的係統性能瓶頸，本篇就針對這個問題看看都有什麼樣的優化思路，以及過往我們都采取過什麼樣的措施來應對。
一、問題現象
從一次具體案例談起：
-
0點整，業務搶售活動開始，幾萬人同時在線搶單。
-
APP到DB的連接池瞬時用完，應用線程開始等待。
-
DB主機cpu使用率迅速100%，DB內部大量wait event。
15分鍾的AWR如下：
每秒redo size11.8MB、每秒事務量1611.9、每秒執行4.3萬、每秒buffer gets 53萬…
這還是15分鍾的平均值，推算某尖峰時刻可能更高：
Top 5events裏麵，log file sync貢獻了12.1%的DB time， 當然還有其它的一些latch等待，這些是另外需要分析優化並解決的話題，本篇先不做討論。
Cpu 使用率100%：
各位看官請繼續先忽略其它event，這裏看過來：
-
logfile sync平均等待時間44ms
-
logfile parallel write平均等待時間9ms。
數據庫的架構是：
-
小型機（solaris）+ Filesystem（Vxfs）+Oracle single instance（11.2.0.3.0）
-
VCS主備的HA、高端SAN存儲
搶售活動過後，此庫的並發壓力仍舊很大，後期不定期還會有LGWR超時報出：
Warning: log write elapsed time 6123ms,size 1KB
每次LGWR超時，都會引起jdbc連接池Suspended：
CannotGetJdbcConnectionException，Could not create pool connection.
The DBMS driver exception was:IO 錯誤: The Network Adapter could not establish the connection
每次應用報錯，DBA都要被拉去批一次。
各位看官，持續好幾個月的這個問題我們不知道怎麼熬過去的，幸虧買有Oracle ACS工程師做我們的背鍋俠，不對，應該是“堅強後盾”。
什麼？你還不知道什麼是Oracle ACS工程師，那還玩什麼Oracle？
強烈建議購買Oracle ACS服務，有Oracle 駐場專家工程師白天的現場陪伴，有飛虎隊之稱的Oracle SSC工程師7*24小時全年無休的隨時守候，你還擔心什麼？
二、問題分析與應對
1存儲層麵
直觀來看，是LGWR寫入redo log較慢，（當然，log file sync 比log file parallel write多出35ms也不正常，這裏麵的因素我們先不考慮），本能的反應是將online redolog切換到更高的存儲上。但存儲方麵看到的監控指標，一直其實並沒有看到有明顯異常。
存儲老大如此說：
存儲提供的SLA為io能力在0.5ms寫，對於特別特征的IO寫響應時間會延長到1ms~3ms,（幾乎對所有目前其它的oracle數據FRA區寫入都是這樣的寫入響應時間，寫fra會比寫redo和data長3~6倍的原因是寫fra的數據塊比較大），為何此庫不能忍受而其他庫能忍受？
這個現象其實我們也討論過，總結如下更加形象一點：
假設A、B兩個庫，平時平均的active session看到A、B庫都是100個，但是A庫平均每個sql（或事務）都是1ms左右的執行時間，B庫平均每個sql（或事務）都是1s左右的，那麼當log file sync堵塞了1s的時候，對A庫的影響就是瞬間堵塞了1000個會話，而對B庫基本沒有什麼感知。
但是迫於應用壓力，更換存儲的措施最後還是實施了，但由於當時還未大量采用全閃存存儲，所以換到另外一台較為空閑的存儲上之後，結果並未得到明顯改善。
這裏說點廢話：
做技術的無法堅持自己的判斷，迫於各種蛋疼的因素，不得不去幹一些廢活，真是奇恥大辱。
後記：
近來存儲開始采用大量閃存技術後，我們已經製定數據庫存儲規範，將所有online redo log要求放到全閃存的DG裏麵，這個措施有很明顯的效果，很多庫的log file sync的效率都在零點幾毫秒。
2操作係統層麵
我們與solaris工程師、symantec工程師、Oracle工程師進行了聯合診斷：
-
通過truss定位到LGWR的寫請求最終都等在KAIO()和pwrite()的調用上，這些是OS層的函數調用。OS pwrite()函數在平時和故障時間段，寫相同300k的數據最快一次調用隻需要0.0017，但是最慢也達到了1.586秒。
-
發現了LGWR被VXFS的vx_rwsleep_rec_lock() 阻塞。
-
隨後solaris工程師祭出大招DTrace，倚天一出、誰與爭鋒！
-
DTrace腳本的目的是抓取LGWR進程其中一個pwrite上下文的call stack。
-
……
中間各方各種pk波折，容我先哭會兒：
滿紙荒唐言，一把辛酸淚。
都說DB堵，誰解其原委？
由於我們的數據庫使用的是文件係統，沒有使用ASM，所以lgwr每次寫入online redo log file，都要經過Filesystem這一層。
第一篇《Oracle高並發係列1：DML引起的常見問題及優化思路》中亮相過的大內第一高手再次發話：“如果問題真的出在vx_rwsleep_rec_lock或者vx_rwunlock上，那麼即使使用direct_io也是無法解決問題的，還是會有inode上的rw lock，但是ODM可以徹底解決這個問題。”
ODM技術其實也是主機同事一直建議啟用的，但是由於對於讀有副作用，所以之前我們一直沒有考慮實施。
沒有其它辦法了，逼上梁山了。
3ODM背景知識
ODM(Oracle Disk Manager)
Whenthe Veritas ODM library is linked, Oracle is able to bypass all caching andlocks at the file system layer and to communicate directly with raw volumes.The SF Oracle RAC implementation of ODM generates performance equivalent toperformance with raw devices while the storage uses easy-to-manage filesystems.
更多信息參考這兩篇MOS文檔：
-
How to Enable/Disable the Veritas ODM forOracle database (文檔 ID 755159.1)
-
How To Validate/Verify ODM (Oracle DiskManager) Is Enabled. (文檔 ID 1352242.1)
4啟用ODM之前需要考慮的事情
ODM雖然能夠加快寫的性能，但是由於啟用ODM繞過了Filesystem這一層，對於數據庫最常見的physical read，就失去了可以從os cache讀到數據的益處了，這個其實對數據庫的一些有物理讀發生的sql影響很大，經過我們的測試驗證（不同IO子係統環境測試結果不一樣，主要看對比值，不是絕對值）：
-
啟用ODM之前，db file sequential read為2ms，
-
啟用ODM之後，db file sequential read 為6ms。
（插播DBA守則1條： 生產任何重要變更之前，都要做測試驗證，必要時做dbreplay負載重演測試。）
所以，為了解決此問題，我們要考慮加大db cache size，增加db cache size可以提高緩存命中率，使得發生物理讀的次數減少。
但是如果還是有SQL隻要發生了物理讀，其效率還是會下降的，這部分的風險始終存在。
那麼如何評估這部分風險到底有多高呢?
大致總結了一個評估表格：
假設數據庫總的讀的request一定的前提下，根據我們統計到的db和os的cache命中率等數據，數據庫隻會有少於2%的讀請求會落在dbcache之外：
而且對於directpath read這種通過PGA的讀的場景， 對於filesystemcache也不會敏感。
*oscache命中率1.32 =(1-98.39%)*82%， 82%是通過kstat大致算出來的oscache命中率。而且這個82%裏麵，可能os本身、oracle軟件本身等都貢獻了一部分， 那麼真正數據庫數據文件在os cache裏麵的命中率其實是還要更低於82%的。
綜合來看，風險較小。
5啟用ODM前後的效果對比：
6一切符合預期，除了log file sync：
-
db file sequential read 等待次數下降了，因為db cache增加了；但是平均單次等待時間變長，因為沒有了OS cache。
-
Log file parallel write 的等待次數增加了，今天的事務量有增加，但是平均等待時間降低了，0.8ms -> 0.3ms ，是啟用ODM的效果。
-
Direct path read平均等待時間沒有怎麼變化，與之前預測一致。
-
之前預測的Db cache size增加20GB之後的cache命中率:
(1-(1-0.9839)*0.8)*100 = 98.712 %
（其中0.8是根據db cache advice得到的物理讀減少的百分比）
調整後實際的命中率，與預測也差不多：
小明：老師，Log file sync平均等待時間沒有怎麼變化，為什麼？
王老師：估計跟_use_adaptive_log_file_sync有關，目前平均都是10ms。如果調整完畢隱參的話，估計會看到更明顯的優化效果。
三、尼瑪，_use_adaptive_log_file_sync又是幹嘛的？
1、在11.2.0.3之前， log file sync是Post/wait的行為：
When a user session commits (or rollsback), the redo information needs to be flushed to the redo logfile. The usersession will post the LGWR to write all redo required from the log buffer tothe redo log file. The user session waits on ‘log file sync’ while waiting forLGWR to post it back to confirm all redo changes are safely on disk.
2、在11.2.0.3以及之後， log file sync是根據內部算法在Post/wait 和 polling兩種形式之間進行切換（這個就叫Adpative Log FileSync）：
Thereare 2 methods by which LGWR and foreground processes can communicate in orderto acknowledge that a commit has completed:
-
Post/wait - traditional method available in previous Oracle releases LGWR explicitly posts all processes waiting for the commit to complete.The advantage of the post/wait method is that sessions should find out almost immediately when the redo has been flushed to disk.
-
Polling - Foreground processes sleep and poll to see if the commit is complete.The advantage of this new method is to free LGWR from having to inform many processes waiting on commit to complete thereby freeing high CPU usage by the LGWR.
Initially the LGWR uses post/wait andaccording to an internal algorithm evaluates whether polling is better. Underhigh system load polling may perform better because the post/waitimplementation typically does not scale well. If the system load is low, thenpost/wait performs well and provides better response times than polling. Oraclerelies on internal statistics to determine which method should be used. Because switching between post/wait and polling incurs an overhead, safe guardsare in place in order to ensure that switches do not occur too frequently.
3、如何定位11.2.0.3以及以後版本的數據庫的log file sync受到了這個行為變化的影響：
當發現數據庫有較多的log file sync，並且其平均等待時間較長，例如7-8ms，且直方圖分布落在1ms以下的較少；但與此同時log file paralle write 的平均等待時間並不長，比如說1-3ms，說明不是因為LGWR寫慢造成的log file sync，而同時應用commit也不是很大量的增長， 則有可能是由於Adpative Log File Sync造成的log file sync。
可以從$ORACLE_BASE/diag/***/trace/*lgwr.trc 這個lgwr的trace文件裏麵看到較為頻繁的post->poll / poll->post 的來回切換：
4、如何禁用adpative log filesync：
alter system set"_use_adaptive_log_file_sync"=false scope=both;
5、如何查看確認修改後的效果：
-
log file paralle write 的平均等待時間不變，修改完畢隱含參數後，log file sync 平均等待時間變短，比如從7ms 降到了3ms。
-
AWR報告或者v$sysstat裏麵的這兩個指標修改前有值，修改後為0：
四、全部調整完畢的效果
對比發現Log fileparallel write 和log file sync 的平均等待時間明顯降低，Logfile parallel write從1ms左右降到當前0.3ms，logfile sync上月大部分都在1.5ms以上，而調整後數據基本都在1ms以下。
調整前：
調整後：
另外，db filesequential read的平均等待時間雖然有增加，但是應用層監控並沒有發現有明顯變慢的情況，所以基本也符合預期。
數據庫啟用ODM對存儲端性能的影響：
-
讀IOPS量巨增，開啟前繁忙時段在1500*2=3000左右，開啟後繁忙時段在5500*2=11000左右，大概有3.6倍。
-
寫IOPS量略有下降，開啟前繁忙時段在300*2=600左右，開啟後繁忙時段在250*2=500左右.
-
讀響應時間從原來的8~9ms左右，降低為7~8ms左右。同時發現讀命中率上升，開啟前是20%~25%，開啟後是30%~50%。原因是頻繁訪問的數據進入了存儲cache中。
-
寫響應時間，開啟前繁忙時段0.25ms左右，開啟後上升到0.5ms左右，分析發現寫命中率有下降，開啟前40%~70%,開啟後是20%~50%。原因是存儲cache是讀寫共享的，如果大量的Read IO占用了內存空間，Write IO的空間就會減少
-
RG使用率在開啟ODM後整體上升了2%左右。
當然，後期我們除了優化log file sync之外，還聯合開發人員一起優化了其它前期發現的一些應用層的數據庫設計問題，例如sql的cursor pin S等等。
在後續的又一次年度搶售活動中，係統表現優異：
每秒的SQL執行量達到7萬+。
高峰期每秒的事務量每秒達到3000。
IO 效率的指標如下：
其中log file sync在在啟用odm並關閉adaptive log file sync後，在搶售活動的高並發壓力下，等待次數有較大增長的情況下，平均等待時間為2ms，效果非常突出。
五、還有可能影響log file sync的其它因素
精力有限，篇幅有限，另外簡單羅列兩點可能因素：
1、進程優先級
1）在10g中，要考慮參數_high_priority_processes是否需要將LGWR進程設置。
2） 在11.2.0.2以上的環境中，詳見SPARC: Reducing High Waitson 'log file sync' on Oracle Solaris SPARC by Increasing Priority of Log Writer(Doc ID 1523164.1)。
3）在11.2.0.4之後，lgwr的進程優先級自動為FX的class的進程優先級。
2、log file switch
適當調整log buffer，適當增加 log file size，可以使得logfile switch的頻率變長， 有機會使得log file switch 的次數減少，間接一定程度上減少log file sync等待發生的幾率。因為有時候log file sync的holder可能是log file switch。 而且log file switch太頻繁會導致後台頻繁報cannot allocatenew log（這個可能也跟CKPT有關，這個因素另當別論）。
也有些Oracle老司機會說，LGWR刷日誌的條件是： user commit、1/3滿、1MB、3秒、在DBWR之前，已經很頻繁了，所以將log buffer調小對於log file sync沒有太大意義。但是，其實是有其它關聯的：
當你發現Oracle數據庫的歸檔日誌切換特別頻繁，比如說1分鍾1-2個，而且磁盤上實際的archivedlog的size遠遠小於online redo logsize的時候，說明有可能是下麵這個問題引發，請參考如下材料分析和調整。
參考文檔：
-
Archived redolog is (significant) smaller than the redologfile.(Doc ID 1356604.1)
-
Archive Logs Are Created With Smaller, Uneven Size Than TheOriginal Redo Logs. Why (Doc ID 388627.1)
簡單來講：
cpu count、log buffer、online redologfile size， 會影響到Oracle計算分配redostrand的個數、以及redo strand的size，以及online redo log被多個redo strand瓜分的機製，進而當Oracle並發redo stand去從logbuffer寫redo entry到redolog file時，就會出現任意一個strand寫滿時，就要求發生log file switch的情況出現。
為解決這個問題，我們製定的規範：
16MB =< Log_buffer <= min(128MB, max(AUTO_SIZE,16M))
300MB =< online redoLog file size <= 1024MB
其中AUTO_SIZE = (number of strand) * (size of perstands)
=(cpu_count/16) * (cpu_count*128)
在上述取值範圍內，再考慮其它方麵（例如log_buffer本身是否足夠、redo log 1小時的切換次數等等），適當調整二者的大小。
原文發布時間為：2016-11-15
本文來自雲棲社區合作夥伴：BDAplus
最後更新：2017-05-13 08:46:53