導(dǎo)讀：東方龍馬致力數(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服務(wù)器進行了重啟，運維人員也對ORACLE數(shù)據(jù)庫服務(wù)重啟。重啟后，系統(tǒng)仍然很慢，最終用戶不斷的抱怨。
根據(jù)技術(shù)人員的反映和之前的操作，我們第一分析就是檢查分析當(dāng)前系統(tǒng)資源使用情況，發(fā)現(xiàn)包括Cpu、IO、內(nèi)存均使用正常，然后開始把焦點放在數(shù)據(jù)庫本身。
首先，從數(shù)據(jù)庫中抓取AWR報告，確認一下整體上的性能問題，整體數(shù)據(jù)庫時間消耗如下：
Snap Id | Snap Time | Sessions | Cursors/Session | |
Begin Snap: | 21589 | 28-Dec-12 09:00:23 | 107 | 3.9 |
End Snap: | 21590 | 28-Dec-12 10:00:25 | 131 | 4.0 |
Elapsed: | 60.04 (mins) | |||
DB Time: | 532.21 (mins) |
我們可以看到，一共收集了60分鐘的報告，DB TIME即數(shù)據(jù)庫實際運行時間占到了532分鐘，即相當(dāng)于差不多9個線程核的CPU滿負載運行。根據(jù)我們對這套系統(tǒng)了解，業(yè)務(wù)量一般不大，數(shù)據(jù)庫壓力也不大，我們暫時確認是數(shù)據(jù)庫整體上性能問題，并判斷可能是鎖（包括lock鎖和Latch鎖）資源等待問題，然后進一步看等待事件：
Event | Waits | Time(s) | Avg wait (ms) | % DB time | Wait Class |
row cache lock | 5,919 | 27,841 | 4704 | 87.19 | Concurrency |
DB CPU | 754 | 2.36 | |||
cursor: pin S wait on X | 268 | 510 | 1904 | 1.60 | Concurrency |
direct path read | 46,380 | 39 | 1 | 0.12 | User I/O |
log file sync | 9,699 | 12 | 1 | 0.04 | Commit |
參考：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秒，相當(dāng)于約450分鐘以上，占了所有運行時間的約87%（27841/(532*60)=87.2%）。理論上這個事件是不能出現(xiàn)在TOP 5事件中的，說明當(dāng)前系統(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 Name | Time (s) | % of DB Time |
parse time elapsed | 25,552.00 | 80.02 |
hard parse elapsed time | 24,988.46 | 78.25 |
sql execute elapsed time | 6,906.29 | 21.63 |
根據(jù)時間模型數(shù)據(jù)，可以看到60分鐘之內(nèi)，用于SQL或PLSQL解釋的時間就占了80%以上，即25552秒，我們可以推測出由于與共享池相關(guān)的row cache lock等待事件導(dǎo)致了SQL解釋出現(xiàn)問題，并最終大量的SQL運行變成緩慢，從于引發(fā)了系統(tǒng)的整體上性問題。
根據(jù)上面的分析數(shù)據(jù)，我們第一步就是先確認數(shù)據(jù)庫配置是否存在問題，對于我們認為不合理的配置，就是調(diào)整到相對合理或我們認為合理的配置。對于當(dāng)前的配置數(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)，當(dāng)前大量的會話都是在等待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的會話當(dāng)前卻未執(zhí)行任何SQL，而且是空閑等待，這是非常不合理的。
這時，我們可以初步確認：當(dāng)前的性能問題和相關(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)，當(dāng)前系統(tǒng)問題與BUG 9776608有一定的符合性：
當(dāng)前版本都是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補丁升級：
考慮到當(dāng)前系統(tǒng)最新版本，我們直接把數(shù)據(jù)庫升級到11.2.0.3.4版本。
考慮到系統(tǒng)升級的安全性，我們先對測試環(huán)境進行PSU補丁的升級，然后再對正式環(huán)境進行升級。
完成升級后，對系統(tǒng)進行監(jiān)控，確認性能問題得到徹底解決！
附錄：問題解決后前后性能對比解釋
Snap Id | Snap Time | Sessions | Cursors/Session | |
Begin Snap: | 21828 | 07-Jan-13 09:00:17 | 81 | 2.7 |
End Snap: | 21829 | 07-Jan-13 10:00:26 | 95 | 3.2 |
Elapsed: | 60.15 (mins) | |||
DB Time: | 59.09 (mins) |
我們同樣收集系統(tǒng)相對壓力比較大的時間段1小時的工作日志，DBTIME 只運行 59分鐘，為存在性能問題時間段（之前同一時間段DBTIME為532分鐘）的10分之一左右。
Event | Waits | Time(s) | Avg wait (ms) | % DB time | Wait Class |
DB CPU | 701 | 19.78 | |||
virtual circuit wait | 51,595 | 37 | 1 | 1.03 | Network |
db file sequential read | 6,676 | 24 | 4 | 0.68 | User I/O |
db file scattered read | 4,163 | 20 | 5 | 0.56 | User I/O |
library cache lock | 9 | 17 | 1895 | 0.48 | Concurrenc |
在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 Name | Time (s) | % of DB Time |
connection management call elapsed time | 2,802.13 | 79.04 |
DB CPU | 701.34 | 19.78 |
sql execute elapsed time | 473.92 | 13.37 |
parse time elapsed | 218.52 | 6.16 |
hard parse elapsed time | 176.29 | 4.97 |
在整個系統(tǒng)時間模型中，解釋的時間僅占到數(shù)據(jù)庫運行時間的6.16%，比之前的80%以上下降了75%以上。
- 蜜度索驥：以跨模態(tài)檢索技術(shù)助力“企宣”向上生長
- 高燃直擊2024世界智能制造博覽會！譜寫智能制造領(lǐng)域全新篇章
- 中泰文化交流新篇章：賽氪與寰宇播客營聯(lián)合中南財經(jīng)政法大學(xué)及多方舉辦泰國留學(xué)生交流活動
- 2025醫(yī)藥數(shù)智營銷創(chuàng)新峰會“金創(chuàng)獎”獎項申報啟動！
- 2024第五屆亞太銀行數(shù)字化創(chuàng)新大會圓滿落幕
- 2024年被稱為“低空經(jīng)濟元年”！倒計時15天 | 2025中國eVTOL創(chuàng)新發(fā)展大會報名中
- 匯聚技術(shù)星火 點亮生態(tài)星空
- GTF2025攜航空和燃氣輪機全產(chǎn)業(yè)鏈優(yōu)勢資源全新回歸上海
- 潮玩風(fēng)暴來襲，2025 ChinaJoy 潮玩手辦及模型展區(qū)招商火爆！
- 普渡機器人發(fā)布首款全人形機器人PUDU D9
- 【創(chuàng)新金融驅(qū)動力】2025中原金融科技節(jié)擘畫中原金融科技新未來！
免責(zé)聲明：本網(wǎng)站內(nèi)容主要來自原創(chuàng)、合作伙伴供稿和第三方自媒體作者投稿，凡在本網(wǎng)站出現(xiàn)的信息，均僅供參考。本網(wǎng)站將盡力確保所提供信息的準(zhǔn)確性及可靠性，但不保證有關(guān)資料的準(zhǔn)確性及可靠性，讀者在使用前請進一步核實，并對任何自主決定的行為負責(zé)。本網(wǎng)站對有關(guān)資料所引致的錯誤、不確或遺漏，概不負任何法律責(zé)任。任何單位或個人認為本網(wǎng)站中的網(wǎng)頁或鏈接內(nèi)容可能涉嫌侵犯其知識產(chǎn)權(quán)或存在不實內(nèi)容時，應(yīng)及時向本網(wǎng)站提出書面權(quán)利通知或不實情況說明，并提供身份證明、權(quán)屬證明及詳細侵權(quán)或不實情況證明。本網(wǎng)站在收到上述法律文件后，將會依法盡快聯(lián)系相關(guān)文章源頭核實，溝通刪除相關(guān)內(nèi)容或斷開相關(guān)鏈接。
