第一章 技術人生系列 · 我和資料中心的故事（第四期）-導致Oracle效能抖動的引數提醒

中亦安圖 | 2016-01-25 21:39

前言

不知不覺，技術人生系列·我和資料中心的故事來到了第四期。小y又和大家見面了！

當您看到業務系統壓測呈現以下波浪形的tps曲線時，你會怎麼下手？

小y(中亦科技)今天要和大家分享的就是這樣一個業務系統壓測效能問題的分析和解決過程。這個問題困擾了客戶相當長一段時間，幸運的是，小y通過遠端在10分鐘定位到了問題的原因並幫助客戶最終解決了問題。需要說明的是，在這個CASE中，只調整資料庫引數是不夠的，還需要做其他分析和調整才可以解決問題。

為了保持原汁原味，同時增加文章的趣味性，小y除了會繼續堅持以往分析報告的寫法外，會嘗試開始引入一些問題處理的心理歷程，希望朋友們可以瞭解到小y的真實工作狀態。

我們能學到什麼

? Oracle資料庫在11.2.0.3及以上的版本上必須要調整的一個重要的效能相關的引數！

? 如何在診斷失敗後堅持或快速調整問題甄別方向的技巧！

? 如何在處理跨團隊/部門的綜合型問題中掌握主動權的一些經驗！

溫馨提示

如果您的高併發、事務型的OLTP核心業務系統中中經常會出現一些效能的抖動。比如交易響應時間突然急劇上升,同時伴隨著ap伺服器埠數/程式活動數/jdbc連線數升高、資料庫每秒DB TIME升高等現象，並且Oracle版本在11.2.0.3或以上，那麼很可能和該文章提到的一個重要引數有關係哦！如果調整引數後還無法解決，可以聯絡小y診斷哦(mian fei de)。

你們的點贊和轉發就是小y繼續堅持分享的動力！

更多Oracle資料庫實戰經驗分享的首發，盡在“中亦安圖”公眾號！歡迎關注。

Part 1

問題來了

上午10點，QQ突然閃了起來，來活了！

小y,有空嗎？幫忙看個awr。

我一會跟你電話說一下情況。

今年他們新上的一個關鍵業務系統，在做上線前的壓力測試時，應用的併發無法達到上線前的併發指標和響應時間指標要求。壓測時TPS的曲線如下所示：發來QQ訊息的是國內一個大型航空公司的DBA，一般的問題他都可以自己解決，這次看上去他遇到麻煩了。

可以看到，壓測時的TPS呈現波浪形，極不穩定。

客戶自己做了很多分析，資源層面，CPU、記憶體使用率、IO均正常，不過客戶自己也發現了，壓測時後端Oracle資料庫中出現了大量的異常等待，主要是gc型別的等待，客戶懷疑是不是私網交換機有問題。但可惜的是，網路團隊卻未檢查出異常。

這個問題，他們也請現有的Oracle服務商進行了分析，但問題遲遲沒有解決。這樣一來，離業務系統要求上線的時間越來越近了，客戶的壓力也越來越大！

小y最近一直在跟這個客戶，從心裡真心希望能有機會為他們提供服務，所以這樣的機會來了，小y自然是打起了十二分精神，準備開始戰鬥。

環境介紹：

作業系統Redhat 64 bit，64C 128G

資料庫 Oracle 11.2.0.3 ,2節點RAC

Part 2

分析過程

2.1分析Oracle資料庫每秒的DB TIME

我們用DB Time除以Elapsed，可以看到每秒DB TIME達到75！這是極度不正常的。

說明資料庫正在經歷嚴重的等待，需要檢視資料庫top等待事件繼續分析。

2.2分析交易時間都消耗到哪了（TOP 5 wait event）

1）節點1等待事件如下所示：

事件分析

?Oracle top 5等待裡，gc buffer busy acquire排在第一位，佔了51.2%，平均每次等待時間達到驚人的277毫秒！這裡的gc buffer busy acquire表示在程式A之前已經有程式B先行向節點2請求同樣的一個資料塊，並且還沒有完成，因此處在等待上。

?排在第二位的是log file sync,佔了18.58%，平均每次達到293毫秒。這裡的log file sync表示當程式發出commit時，需要等lgwr後臺進行將log buffer中的改變向量持久化到磁碟中的redo log中所發生的等待。

?排在第三位的是DB CPU，在一個小時的取樣裡，總的等待時間是24648秒，也就是說大概佔了7顆CPU時間，該伺服器配置了64顆CPU，因此平均CPU使用率只用到了10%。這裡小y順便提一下，通常情況下，我們期望DB CPU的比例越高越好，這樣就意味著SQL在執行的過程中，幾乎不用發生等待，SQL的響應時間也就越快。但不代表就沒問題，比如高邏輯讀的SQL，如果要操作的資料都在記憶體中，也會導致DB CPU過高，此時就需要對高邏輯讀的SQL進行優化了，從而降低DB CPU。

?排在第四位的是direct path read,平均等待時間也到了153毫秒。這裡的direct path read表示程式直接將資料塊讀入PGA記憶體而不是讀進buffer cache共享記憶體。這種情況下，IO的吞吐顯然會更大，每個程式都各自讀各自的哪怕是相同的資料。如果不同的程式同時讀取的是相同的資料，並且讀進共享記憶體，那麼只需要一個程式負責讀取，其他程式直接操作記憶體中的資料即可，此時IO吞吐會小很多。

?排在第五位的是buffer busy wait,平均等待時間到了驚人的499毫秒。這裡的buffer busy wait表示當兩個或者兩個以上的程式需要同時對一個資料塊進行寫/寫、寫/讀操作時發生衝突，即熱塊衝突。

看到這裡，小Y已經基本知道答案了！

不過從嚴謹的角度，還是要把RAC 2節點的等待事件也稍微過一下。

2）節點2等待事件如下所示：

和節點1相比，沒有buffer busy wait,多了gc current block busy。

總體來說，兩個節點的等待事件差別不大！

2.3 前2分鐘裡小y的頭腦風暴

2.3.1是不是RAC私網的問題？

看到這裡，也許有人會說:

gc等待那麼高，是不是把另外一個RAC節點臨時關掉，問題就解決了呢？

首先答案是NO！其次，這樣的做法是生產出現緊急gc效能問題時可以臨時採用的，但是對於這樣一個case,客戶顯然是不接受的。

小y從技術層面來回答下這個問題。

首先，如下圖所示

兩個節點的私網不過是每秒3M，而RAC兩臺伺服器為私網配置的是千兆交換機。

其次，RAC兩個節點的CPU和記憶體均處於低位，也就沒有出現因為資源問題導致一個節點執行緩慢，繼而導致無法快速響應另外一個節點的gc請求的情況。

如果是該類問題，我們通常還可以看到gc*congested*型別的等待（擁堵）。

2.3.2是不是SQL效率導致gc/bbw/direct path read的問題？

其中bbw即buffer busy wait,

gc即表示gc buffer busy acquire等gc等待。

也許有人會說：

gc等待那麼高，還有buffer busy wait等待,如果SQL效率足夠高，那麼訪問的資料塊就少了，那麼程式發生gc請求的個數就很少，同時由於讀/寫造成的熱塊衝突自然也就沒了。

答案是NO！

見下圖，可以看到該應用還是寫的相當不錯的，大部分SQL都控制在100個邏輯讀以下，只有3個SQL的邏輯讀在幾千到幾萬，這樣的SQL效率和邏輯讀數量不足以導致如此高的gc/bbw等待！另外，落到SQL效率不高這個點上，是沒有辦法解釋log file sync/direct path read也處於平均單次長時間等待的！錯誤的方向是不能解決根本問題的！也就是說，即使你再花精力優化掉這幾個邏輯讀稍微高一些的SQL，壓測的問題還是會依然存在，因為這不是根本原因，優化SQL對於這個CASE而言是錦上添花而非雪中送炭！

2.3.3是不是direct path read導致IO頻寬佔滿的問題？

也許有人會說，會不會有這樣一種可能：

? 先是direct path read導致IO頻寬被佔滿

說明：多個程式把資料塊讀進PGA私有記憶體而不是buffer cache共享記憶體，以多塊讀16計算，每個BLOCK 8K，每個程式可以讀取30M左右，15個以上的程式同時多塊讀就可以把hba卡頻寬佔滿，設定10949 event可禁止該特性。

? 由於IO頻寬被佔滿，影響了lgwr寫日誌的響應時間，繼而導致log file sync等待長。

? 而log file sync又是gc和buffer busy wait的一個環節，從而將gc和buffer busy等待時間拉高，因此出現了AWR報告的等待？

首先，可以做出該假設的朋友，可以發小y發一份簡歷，說明你對資料庫有非常深入的理解，並且有非常豐富的TroubleShooting經驗，而且也已經不在割裂的分析問題的層面上了！

歡迎你加入中亦科技DBA團隊！來了就是兄弟，我們一起並肩戰鬥，一起挑戰各種疑難問題，一起分享收益！

簡歷請發至51994106@qq.com

那麼Log file sync和gc有什麼關係呢？

引用一張RAC SG的圖，其中原理如下圖所示

從上圖可以看到：

gc類的請求，在第二步中包含了lgwr程式寫日誌的過程，

即log file sync是gc請求的一個子步驟，嚴格來說，該步驟叫gc log flush sync.

但答案依然是NO！

從下圖load profile中可以看到，每秒的物理讀是498個BLOCK，每個BLOCK是8K，也就是說每秒的IO才4M左右。IOPS和IO頻寬都非常低，顯然不是該問題！

2.3.42.小y快速鎖定問題分析方向！

小y這兩分鐘裡如同上述的分析一樣，飛速的進行著各種假設和排除、問題串聯。

很快小y就鎖定了問題的分析方向——那就是要把分析焦點放在log file sync等待上！

原因很簡單，通過分析top 5等待，不難看到，他們之間是有關聯關係的：

log file sync是gc和buffer busy wait的一個環節！（見2.3.3中的圖）

如果log file sync等待解決了，自然gc*等待和buffer busy wait等待也就下去了！

問題也就得到解決了！

2.4 聚焦在“log file sync“等待上

從上文，我們已經知道，“log file sync”等待事件表示：

當程式發出commit時，需要等lgwr後臺進行將log buffer中的改變向量持久化到磁碟中的redo log的過程中所發生的等待。因此，最常見的是lgwr寫日誌寫的慢，或者是因為commit太頻繁所導致！

接下來小y依次檢查了這兩個方面。

ORACLE當中，如果lgwr寫日誌寫的慢，會體現到log file parallel write單次響應時間慢上。

節點1

節點2

可以看到，兩個節點無論是log file parallel write還是gc log flush sync都只在5個毫秒以下，其中log file parallel write更是隻有1毫秒和3毫秒。排除該問題！

接下來檢查commit次數！

如下圖所示,每秒的transactions（commits/rollbacks）只有48個！

小y服務過的一些大型銀行的高併發的核心繫統中，包括每秒事務數在10000以上的，log file sync也都控制在10個毫秒以內。所以每秒transactions只有48個是非常小的指標，不至於引起這麼嚴重的等待！

2.5 原因基本定位並開始第一次調整

分析到了這裡,小y已經已經找到本次壓測的根本原因了，只需要調整驗證即可。

建議朋友們，讀到這裡也可以先停一下，看看自己是否找到了問題原因。

也就是客戶AWR報告發過來後的兩分鐘，小y告訴他

“我知道原因了，你把lgwr程式的trace發我最後確認一下，我們就開始調整”

其實並不奇怪，這樣的case小y在幾年前做大量系統升級到11g時就遇到過N次!客戶很驚訝，他甚至還來不及電話小y，小y怎麼可以這樣…

這應該是一個上線前的標配，雖然現象不一樣，但本質上是一個問題。

這也就是小y標題中要重點提示大家的一個重要的資料庫引數。

如果Log file sync等待事件很長，但是lgwr寫日誌的時間很快，並且commit次數也不大的話，那就是在發起commit的程式和lgwr之間的通訊環節上出了問題。

關鍵知識點:

ORACLE從11G開始，為lgwr寫日誌引入了polling機制，而在以前只有post/wait機制。

同時引入了一個隱含引數，"_use_adaptive_log_file_sync"，即在兩個機制之間自適應的切換。在11.2.0.3以下，該引數的預設值為false,即只啟用post/wait機制。

從11.2.0.3開始，該引數的預設值為true,即Oracle會在post/wait機制和polling機制自適應。

? Post/wait進位制下，lgwr程式在寫完log buffer中的改變向量後，立刻通知待commit的程式，因此log file sync等待時間短，但lgwr相對來說，負擔要重一些。畢竟12C以下lgwr程式只有1個，當同時commit的程式比較多的時候，通知待commit的程式也是一種負擔。

? Polling模式下，待commit的程式，通知lgwr程式進行寫入操作後，會進入sleep環節，並在timeout後去看是否log buffer中的內容被寫入了磁碟，lgwr程式不再單獨通知待commit的程式寫已經完成。Polling機制下，解放了一部分lgwr的工作，但是會帶來待commit的程式長時間處於log file sync等待下。對於交易型的系統而言，該機制是極度不適用的！

在post/wait和polling機制之間的切換，ORACLE會記錄到lgwr程式的trace當中，如下所示。

當切換到polling模式下時，很容易引起log file sync等待而影響交易的響應時間！

Log file sync switching to polling

……

Log file sync switching to post/wait

在Oracle 11.2.0.3以下，建議關閉自適應log file sync,務必讓lgwr程式執行在post/wait機制下，以確保資料庫效能不會出現大的抖動！關閉的命令如下，可線上修改！因此，小y在這裡提示各位

alter system set "_use_adaptive_log_file_sync"=false sid='*';

沒錯，小y的第一次調整措施就是調整該引數為false。

2.6 第一次調整後的結果讓是失望！

線上調整引數後，為了安全起見，客戶把兩個節點資料庫都重啟了一遍。

並且重新做了壓力測試,重新收集後的AWR報告如下所示！

看到節點1的這個AWR報告，gc等待和log file sync等待依然存在，並且看上去單次等待的時間更長了！

難道小y的分析出了問題? 或者說，小y這次遇到了好幾個摻雜在一起的問題？冷靜了一下，RAC的問題，切記只看單個節點，因此，小y讓客戶出了節點2的AWR報告，調整後節點2的awr報告如下圖所示：

可以看到：

雖然等待還在，但節點2的log file sync等待沒有了！這說明這次調整還是起到效果了的！

並且細心的朋友，可能已經發現了，節點1的第一位的等待gc buffer busy acquire完全沒有了（說明節點2 log file sync快了），從gc buffer busy acquire變成了gc buffer busy release。這不正好說明調整還是起到作用了麼？

到這裡，先不要著急，這裡因為節點1依然存在log file sync,所以節點2的gc buffer busy acquire還依然存在！那麼接下來，小y就要集中精力再解決掉節點1的log file sync就好了！

2.7 真相浮出水面（懷疑一切）

總結一下，這裡調整log file sync自適應後，問題還是沒有得到解決，那麼回到傳統思路上，最可能的問題那就還是lgwr程式寫日誌慢了！雖然awr報告中log file parallel write指標只有幾個毫秒，但是awr報告畢竟是一個工具，提供的只是參考值，因此我們還是要抱著懷疑一切的態度，再來塞查一次！

這一次，我們來實時觀察lgwr程式寫日誌的情況。發出SQL語句，結果如下圖所示：

可以看到：

? RAC兩個節點中，只有1個節點出現log file parallel write的等待，剛好和前面的所有分析相互吻合！

? 在state是waiting的情況下，log file parallel等待的seq#都是35693，但是seconds_in_wait達到了21秒。簡單來說，就是lgwr程式寫一個IO需要21秒！

至此，我們可以肯定，IO子系統有問題，需要重點排查IO路徑下的光纖線、SAN交換機、儲存的報錯和效能情況。

2.8 如何進一步證明IO路徑環節有問題（跨部門合作）

考慮到客戶那邊管儲存的團隊/部門可能不承認資料庫的IO慢的證據，同時為了讓對方增加排查力度，小y讓客戶發出以下命令，檢視多路徑軟體的IO情況，結果如下圖所示：

節點1上出現明顯的IO ERROR，並且在持續增加！

繼續檢查節點2，發現節點2上沒有任何IO ERROR！

回顧前面的分析，節點2在調整資料庫自適應log file sync為false後，並且沒有出現IO ERROR，因此已經沒有log file sync。

至此，分析結束！所有問題都得到了完美的解釋！

找到原因了，還拿到了說服力極強的證據，客戶終於鬆了一口氣，不怕儲存團隊不認賬了！

2.9 問題得到圓滿解決

在鐵的證據面前，客戶的儲存團隊沒有再掙扎，而是開始認認真真逐個在排查，最終在更換了光纖線後問題得到圓滿解決。以下是更換光纖線後再次壓測的等待事件！

壓測的TPS曲線從原來的波浪形：

變成了如下的良好曲線

Part 3

問題原因和總結和風險提示

3.1 問題原因總結

該航空客戶業務上線時壓測無法達到併發和響應時間指標的原因在於同時遇到了兩個混在一起的問題：

1）Oracle 11.2.0.3上log file sync預設開啟自適應，當切換到polling模式後，導致log file sync等待時間變長，而log file sync是gc和buffer busy wait的一個環節，因此導致大量的等待

小y將"_use_adaptive_log_file_sync"調整為false後，就解決了一部分的log file sync等待的問題

2）由於節點1的光纖線存在質量問題，會導致IO錯誤，繼而導致IO重發，影響了lgwr寫日誌的效能。

在調整資料庫引數預設值並且更換光纖線後，問題得到圓滿解決。

壓測的TPS曲線從原來的波浪形

變成了如下的良好曲線

3.2 解決問題的關鍵點回顧

1）對Oracle等待事件不要割裂的來分析

小y在本case中通過梳理等待事件的共同點為log file sync,從而找到了突破口

2）瞭解不同版本資料庫的特性和行為

小y平時在不斷了解11g的新特性，並且通過大量的故障處理深入理解了這些特性，因此，當log file sync出現的時候，可以很快定位到新特性引起

3）不要完全相信AWR報告，他只是個工具，要懷疑一切去驗證。

在這個case中，awr報告的指標並不能真實反映lgwr寫效能的情況，要懷疑一切

4）一個Oracle服務人員，如果只懂資料庫，就會出現你懷疑這懷疑那，但是其他人根本不認賬的情況，因此必須掌握更多的包括作業系統、儲存、網路、中介軟體的技能。當然了，找一家綜合服務能力強的服務商也是不錯的選擇。

在這個case中，小y通過多路徑的命令，找到了直接證據，最終獲得了其他團隊的大力度排查也是這次問題最終解決的關鍵。

風險提示

ORACLE從11G開始，為lgwr寫日誌引入了polling機制，而在以前只有post/wait機制。

同時引入了一個隱含引數，"_use_adaptive_log_file_sync"，即在兩個機制之間自適應的切換。在11.2.0.3以下，該引數的預設值為false,即只啟用post/wait機制。

從11.2.0.3開始，該引數的預設值為true,即Oracle會在post/wait機制和polling機制自適應。

? Post/wait進位制下，lgwr程式在寫完log buffer中的改變向量後，立刻通知待commit的程式，因此log file sync等待時間短，但lgwr相對來說，負擔要重一些。畢竟12C以下lgwr程式只有1個，當同時commit的程式比較多的時候，通知待commit的程式也是一種負擔。

? Polling模式下，待commit的程式，通知lgwr程式進行寫入操作後，會進入sleep環節，並在timeout後去看是否log buffer中的內容被寫入了磁碟，lgwr程式不再單獨通知待commit的程式寫已經完成。Polling機制下，解放了一部分lgwr的工作，但是會帶來待commit的程式長時間處於log file sync等待下。對於交易型的系統而言，該機制是極度不適用的！

進位制之間的切換回記錄到lgwr程式的trace當中，如下所示。

當切換到polling模式下時，很容易引起log file sync等待而影響交易的響應時間！

Log file sync switching to polling

……

Log file sync switching to post/wait

因此，小y在這裡提示各位。

在Oracle 11.2.0.3以下，建議關閉自適應log file sync,務必讓lgwr程式執行在post/wait機制下，以確保資料庫不會出現嚴重的效能抖動！關閉的命令如下，可線上修改！

About Me

....................................................................................................................................................

本文來自於微信公眾號轉載文章，若有侵權，請聯絡小麥苗及時刪除

ITPUB BLOG：http://blog.itpub.net/26736162

QQ：642808185 若加QQ請註明您所正在讀的文章標題

【版權所有，文章允許轉載，但須以連結方式註明源地址，否則追究法律責任】

....................................................................................................................................................

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/26736162/viewspace-2083717/，如需轉載，請註明出處，否則將追究法律責任。