導讀：東方龍馬致力數(shù)據(jù)庫 | 中間件領(lǐng)域20余年，積累很多寶貴的業(yè)內(nèi)經(jīng)驗和專業(yè)人才，今天由東方龍馬高級工程師阮文強，向大家講述一次因BUG原因引發(fā)的性能故障分析與處理案例。希望對你有所幫助。
一般情況下，對于ORACLE數(shù)據(jù)庫來說，一說到性能問題，我們都是聯(lián)想到是否SQL執(zhí)行出現(xiàn)了性能問題?是否配置不合理?是否CPU和IO等操作系統(tǒng)資源使用出現(xiàn)問題?但最近我們遇到了一個由于ORACLE BUG引發(fā)的數(shù)據(jù)庫性能問題。
背景：用戶反饋有一套系統(tǒng)運行很慢，包括所有的操作如一般的登錄、查詢、編輯、報表輸出都突然變得很慢，開發(fā)人員和運維人員都做了相關(guān)的檢查和一般分析，但都沒發(fā)現(xiàn)任何可疑的地方，開發(fā)人員還對中間件tomcat服務器進行了重啟，運維人員也對ORACLE數(shù)據(jù)庫服務重啟。重啟后，系統(tǒng)仍然很慢，最終用戶不斷的抱怨。
根據(jù)技術(shù)人員的反映和之前的操作，我們第一分析就是檢查分析當前系統(tǒng)資源使用情況，發(fā)現(xiàn)包括Cpu、IO、內(nèi)存均使用正常，然后開始把焦點放在數(shù)據(jù)庫本身。
首先，從數(shù)據(jù)庫中抓取AWR報告，確認一下整體上的性能問題，整體數(shù)據(jù)庫時間消耗如下：
Snap IdSnap TimeSessionsCursors/Session
Begin Snap:2158928-Dec-12 09:00:231073.9
End Snap:2159028-Dec-12 10:00:251314.0
Elapsed:60.04 (mins)
DB Time:532.21 (mins)
我們可以看到，一共收集了60分鐘的報告，DB TIME即數(shù)據(jù)庫實際運行時間占到了532分鐘，即相當于差不多9個線程核的CPU滿負載運行。根據(jù)我們對這套系統(tǒng)了解，業(yè)務量一般不大，數(shù)據(jù)庫壓力也不大，我們暫時確認是數(shù)據(jù)庫整體上性能問題，并判斷可能是鎖(包括lock鎖和Latch鎖)資源等待問題，然后進一步看等待事件：
EventWaitsTime(s)Avg wait (ms)% DB timeWait Class
row cache lock5,91927,841470487.19Concurrency
DB CPU7542.36
cursor: pin S wait on X26851019041.60Concurrency
direct path read46,3803910.12User I/O
log file sync9,6991210.04Commit
參考：row cache lock 解釋：
Row Cache Lock：
When DDLs execute, it must acquire a row cache latch to lock the Data Dictionary information. The shared pool contains a cache of rows from the data dictionary that helps reduce physical I/O to the data dictionary tables. This allows locking of individual data dictionary rows.
我們根據(jù)后臺等待事件發(fā)現(xiàn)，row cache lock等待事件占了87%以上，占了運行時間27841秒，相當于約450分鐘以上，占了所有運行時間的約87%(27841/(532*60)=87.2%)。理論上這個事件是不能出現(xiàn)在TOP 5事件中的，說明當前系統(tǒng)性能差、數(shù)據(jù)庫運行時間消耗時間長都是由row cache lock等待事件引發(fā)起。我們再去看整體時間使用模型：
Time Model Statistics
Total time in database user-calls (DB Time): 31932.9s
Statistics including the word "background" measure background process time, and so do not contribute to the DB time statistic
Ordered by % or DB time desc, Statistic name
Statistic NameTime (s)% of DB Time
parse time elapsed25,552.0080.02
hard parse elapsed time24,988.4678.25
sql execute elapsed time6,906.2921.63
根據(jù)時間模型數(shù)據(jù)，可以看到60分鐘之內(nèi)，用于SQL或PLSQL解釋的時間就占了80%以上，即25552秒，我們可以推測出由于與共享池相關(guān)的row cache lock等待事件導致了SQL解釋出現(xiàn)問題，并最終大量的SQL運行變成緩慢，從于引發(fā)了系統(tǒng)的整體上性問題。
根據(jù)上面的分析數(shù)據(jù)，我們第一步就是先確認數(shù)據(jù)庫配置是否存在問題，對于我們認為不合理的配置，就是調(diào)整到相對合理或我們認為合理的配置。對于當前的配置數(shù)據(jù)，我們主要對SGA和相關(guān)的內(nèi)存組件進行了調(diào)整，調(diào)整配置如下：
同時，對操作系統(tǒng)內(nèi)核的一些參數(shù)據(jù)進行了調(diào)整：
通過調(diào)整后，根據(jù)對數(shù)據(jù)庫的監(jiān)控，系統(tǒng)性能有一點提升，可沒從實質(zhì)上解決整體上系統(tǒng)慢的性能問題。
我們繼續(xù)深入分析，通過hanganalyz level 3進行跟蹤，得到相關(guān)TRACE文件，關(guān)鍵內(nèi)容如下：
我們發(fā)現(xiàn)，當前大量的會話都是在等待nodenum=349(session id=350)的會話，然后再看具體會話TRACE信息，如下：
從上面的信息我們發(fā)現(xiàn)，上面row cache lock 的引發(fā)主要是由于在執(zhí)行常規(guī)SQL語句等待另一個會話(SID=350)釋放相關(guān)資源，可我們發(fā)現(xiàn)SID=350的會話當前卻未執(zhí)行任何SQL，而且是空閑等待，這是非常不合理的。
這時，我們可以初步確認：當前的性能問題和相關(guān)的SQL執(zhí)行并沒有直接聯(lián)系，很大概率是ORACLE的內(nèi)部運行機制出現(xiàn)問題，即可能是BUG的問題!
我們通過METALINK發(fā)現(xiàn)該問題進一步確認是BUG方面的問題，如下：
注：具體見METALINK DOC ID：1162566.1
從上面的信息我們發(fā)現(xiàn)，當前系統(tǒng)問題與BUG 9776608有一定的符合性：
當前版本都是11.2.0.0.1
出現(xiàn)大量row cache lock，而且都是短的大量的row cache lock等待。
通過進一步分析系統(tǒng)底層調(diào)用都是ksedsts()+644<- ksdxfstk() +44<- ksdxcb()……等函數(shù)開頭。
根據(jù)文檔要求，該問題可升級到11.2.0.2以上版本或安裝補丁包patch9776608解決問題。
隨后，我們配合運維人員進行系統(tǒng)ORACLE數(shù)據(jù)庫基于PSU補丁升級：
考慮到當前系統(tǒng)最新版本，我們直接把數(shù)據(jù)庫升級到11.2.0.3.4版本。
考慮到系統(tǒng)升級的安全性，我們先對測試環(huán)境進行PSU補丁的升級，然后再對正式環(huán)境進行升級。
完成升級后，對系統(tǒng)進行監(jiān)控，確認性能問題得到徹底解決!
附錄：問題解決后前后性能對比解釋
Snap IdSnap TimeSessionsCursors/Session
Begin Snap:2182807-Jan-13 09:00:17812.7
End Snap:2182907-Jan-13 10:00:26953.2
Elapsed:60.15 (mins)
DB Time:59.09 (mins)
我們同樣收集系統(tǒng)相對壓力比較大的時間段1小時的工作日志，DBTIME 只運行 59分鐘，為存在性能問題時間段(之前同一時間段DBTIME為532分鐘)的10分之一左右。
EventWaitsTime(s)Avg wait (ms)% DB timeWait Class
DB CPU70119.78
virtual circuit wait51,5953711.03Network
db file sequential read6,6762440.68User I/O
db file scattered read4,1632050.56User I/O
library cache lock91718950.48Concurrenc
在TOP 5事件中，不再存在row cache lock等待事件!
Time Model Statistics
Total time in database user-calls (DB Time): 3545.3s
Statistics including the word "background" measure background process time, and so do not contribute to the DB time statistic
Ordered by % or DB time desc, Statistic name
Statistic NameTime (s)% of DB Time
connection management call elapsed time2,802.1379.04
DB CPU701.3419.78
sql execute elapsed time473.9213.37
parse time elapsed218.526.16
hard parse elapsed time176.294.97
在整個系統(tǒng)時間模型中，解釋的時間僅占到數(shù)據(jù)庫運行時間的6.16%，比之前的80%以上下降了75%以上。
申請創(chuàng)業(yè)報道，分享創(chuàng)業(yè)好點子。點擊此處，共同探討創(chuàng)業(yè)新機遇！
