導讀：東方龍馬致力數(shù)據(jù)庫 | 中間件領域20余年，積累很多寶貴的業(yè)內經(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ā)人員和運維人員都做了相關的檢查和一般分析，但都沒發(fā)現(xiàn)任何可疑的地方，開發(fā)人員還對中間件tomcat服務器進行了重啟，運維人員也對ORACLE數(shù)據(jù)庫服務重啟。重啟后，系統(tǒng)仍然很慢，最終用戶不斷的抱怨。
根據(jù)技術人員的反映和之前的操作，我們第一分析就是檢查分析當前系統(tǒng)資源使用情況，發(fā)現(xiàn)包括Cpu、IO、內存均使用正常，然后開始把焦點放在數(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分鐘，即相當于差不多9個線程核的CPU滿負載運行。根據(jù)我們對這套系統(tǒng)了解，業(yè)務量一般不大，數(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秒，相當于約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 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分鐘之內，用于SQL或PLSQL解釋的時間就占了80%以上，即25552秒，我們可以推測出由于與共享池相關的row cache lock等待事件導致了SQL解釋出現(xiàn)問題，并最終大量的SQL運行變成緩慢，從于引發(fā)了系統(tǒng)的整體上性問題。
根據(jù)上面的分析數(shù)據(jù)，我們第一步就是先確認數(shù)據(jù)庫配置是否存在問題，對于我們認為不合理的配置，就是調整到相對合理或我們認為合理的配置。對于當前的配置數(shù)據(jù)，我們主要對SGA和相關的內存組件進行了調整，調整配置如下：
同時，對操作系統(tǒng)內核的一些參數(shù)據(jù)進行了調整：
通過調整后，根據(jù)對數(shù)據(jù)庫的監(jiān)控，系統(tǒng)性能有一點提升，可沒從實質上解決整體上系統(tǒng)慢的性能問題。
我們繼續(xù)深入分析，通過hanganalyz level 3進行跟蹤，得到相關TRACE文件，關鍵內容如下：
我們發(fā)現(xiàn)，當前大量的會話都是在等待nodenum=349(session id=350)的會話，然后再看具體會話TRACE信息，如下：
從上面的信息我們發(fā)現(xiàn)，上面row cache lock 的引發(fā)主要是由于在執(zhí)行常規(guī)SQL語句等待另一個會話（SID=350）釋放相關資源，可我們發(fā)現(xiàn)SID=350的會話當前卻未執(zhí)行任何SQL，而且是空閑等待，這是非常不合理的。
這時，我們可以初步確認：當前的性能問題和相關的SQL執(zhí)行并沒有直接聯(lián)系，很大概率是ORACLE的內部運行機制出現(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)底層調用都是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 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)檢索技術助力“企宣”向上生長
- CSDN「智研社」第四期活動開啟-共敘大模型驅動的云產(chǎn)業(yè)變革與應用創(chuàng)新
- 助推低空經(jīng)濟發(fā)展 2025北京無人機展會 歡迎您
- 第十五屆中國國際納米技術產(chǎn)業(yè)博覽會
- CHInano 2025 第十五屆中國國際納米技術產(chǎn)業(yè)博覽會
- 文旅類：品牌較量的新高地丨第十六屆虎嘯獎征賽進行中！
- 答案即將揭曉|2024視聽圈，誰在突破重圍，誰在改變未來？
- 十余年煉就細分王者，這家激光企業(yè)“毫厘之間見真功”
- 銅業(yè)龍頭齊聚南昌！SMM銅業(yè)大會第一波進程函搶先看！
- IBS 2025 第十三屆中國國際生物質能源與有機固廢資源化利用高峰論壇
免責聲明：本網(wǎng)站內容主要來自原創(chuàng)、合作伙伴供稿和第三方自媒體作者投稿，凡在本網(wǎng)站出現(xiàn)的信息，均僅供參考。本網(wǎng)站將盡力確保所提供信息的準確性及可靠性，但不保證有關資料的準確性及可靠性，讀者在使用前請進一步核實，并對任何自主決定的行為負責。本網(wǎng)站對有關資料所引致的錯誤、不確或遺漏，概不負任何法律責任。任何單位或個人認為本網(wǎng)站中的網(wǎng)頁或鏈接內容可能涉嫌侵犯其知識產(chǎn)權或存在不實內容時，應及時向本網(wǎng)站提出書面權利通知或不實情況說明，并提供身份證明、權屬證明及詳細侵權或不實情況證明。本網(wǎng)站在收到上述法律文件后，將會依法盡快聯(lián)系相關文章源頭核實，溝通刪除相關內容或斷開相關鏈接。
