域名預(yù)訂/競(jìng)價(jià)，好“米”不錯(cuò)過(guò)
導(dǎo)讀：東方龍馬致力數(shù)據(jù)庫(kù) | 中間件領(lǐng)域20余年，積累很多寶貴的業(yè)內(nèi)經(jīng)驗(yàn)和專業(yè)人才，今天由東方龍馬高級(jí)工程師阮文強(qiáng)，向大家講述一次因BUG原因引發(fā)的性能故障分析與處理案例。希望對(duì)你有所幫助。
一般情況下，對(duì)于ORACLE數(shù)據(jù)庫(kù)來(lái)說(shuō)，一說(shuō)到性能問(wèn)題，我們都是聯(lián)想到是否SQL執(zhí)行出現(xiàn)了性能問(wèn)題?是否配置不合理?是否CPU和IO等操作系統(tǒng)資源使用出現(xiàn)問(wèn)題?但最近我們遇到了一個(gè)由于ORACLE BUG引發(fā)的數(shù)據(jù)庫(kù)性能問(wèn)題。
背景：用戶反饋有一套系統(tǒng)運(yùn)行很慢，包括所有的操作如一般的登錄、查詢、編輯、報(bào)表輸出都突然變得很慢，開發(fā)人員和運(yùn)維人員都做了相關(guān)的檢查和一般分析，但都沒(méi)發(fā)現(xiàn)任何可疑的地方，開發(fā)人員還對(duì)中間件tomcat服務(wù)器進(jìn)行了重啟，運(yùn)維人員也對(duì)ORACLE數(shù)據(jù)庫(kù)服務(wù)重啟。重啟后，系統(tǒng)仍然很慢，最終用戶不斷的抱怨。
根據(jù)技術(shù)人員的反映和之前的操作，我們第一分析就是檢查分析當(dāng)前系統(tǒng)資源使用情況，發(fā)現(xiàn)包括Cpu、IO、內(nèi)存均使用正常，然后開始把焦點(diǎn)放在數(shù)據(jù)庫(kù)本身。
首先，從數(shù)據(jù)庫(kù)中抓取AWR報(bào)告，確認(rèn)一下整體上的性能問(wèn)題，整體數(shù)據(jù)庫(kù)時(shí)間消耗如下：
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分鐘的報(bào)告，DB TIME即數(shù)據(jù)庫(kù)實(shí)際運(yùn)行時(shí)間占到了532分鐘，即相當(dāng)于差不多9個(gè)線程核的CPU滿負(fù)載運(yùn)行。根據(jù)我們對(duì)這套系統(tǒng)了解，業(yè)務(wù)量一般不大，數(shù)據(jù)庫(kù)壓力也不大，我們暫時(shí)確認(rèn)是數(shù)據(jù)庫(kù)整體上性能問(wèn)題，并判斷可能是鎖(包括lock鎖和Latch鎖)資源等待問(wèn)題，然后進(jìn)一步看等待事件：
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ù)后臺(tái)等待事件發(fā)現(xiàn)，row cache lock等待事件占了87%以上，占了運(yùn)行時(shí)間27841秒，相當(dāng)于約450分鐘以上，占了所有運(yùn)行時(shí)間的約87%(27841/(532*60)=87.2%)。理論上這個(gè)事件是不能出現(xiàn)在TOP 5事件中的，說(shuō)明當(dāng)前系統(tǒng)性能差、數(shù)據(jù)庫(kù)運(yùn)行時(shí)間消耗時(shí)間長(zhǎng)都是由row cache lock等待事件引發(fā)起。我們?cè)偃タ凑w時(shí)間使用模型：
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í)間模型數(shù)據(jù)，可以看到60分鐘之內(nèi)，用于SQL或PLSQL解釋的時(shí)間就占了80%以上，即25552秒，我們可以推測(cè)出由于與共享池相關(guān)的row cache lock等待事件導(dǎo)致了SQL解釋出現(xiàn)問(wèn)題，并最終大量的SQL運(yùn)行變成緩慢，從于引發(fā)了系統(tǒng)的整體上性問(wèn)題。
根據(jù)上面的分析數(shù)據(jù)，我們第一步就是先確認(rèn)數(shù)據(jù)庫(kù)配置是否存在問(wèn)題，對(duì)于我們認(rèn)為不合理的配置，就是調(diào)整到相對(duì)合理或我們認(rèn)為合理的配置。對(duì)于當(dāng)前的配置數(shù)據(jù)，我們主要對(duì)SGA和相關(guān)的內(nèi)存組件進(jìn)行了調(diào)整，調(diào)整配置如下：
同時(shí)，對(duì)操作系統(tǒng)內(nèi)核的一些參數(shù)據(jù)進(jìn)行了調(diào)整：
通過(guò)調(diào)整后，根據(jù)對(duì)數(shù)據(jù)庫(kù)的監(jiān)控，系統(tǒng)性能有一點(diǎn)提升，可沒(méi)從實(shí)質(zhì)上解決整體上系統(tǒng)慢的性能問(wèn)題。
我們繼續(xù)深入分析，通過(guò)hanganalyz level 3進(jìn)行跟蹤，得到相關(guān)TRACE文件，關(guān)鍵內(nèi)容如下：
我們發(fā)現(xiàn)，當(dāng)前大量的會(huì)話都是在等待nodenum=349(session id=350)的會(huì)話，然后再看具體會(huì)話TRACE信息，如下：
從上面的信息我們發(fā)現(xiàn)，上面row cache lock 的引發(fā)主要是由于在執(zhí)行常規(guī)SQL語(yǔ)句等待另一個(gè)會(huì)話(SID=350)釋放相關(guān)資源，可我們發(fā)現(xiàn)SID=350的會(huì)話當(dāng)前卻未執(zhí)行任何SQL，而且是空閑等待，這是非常不合理的。
這時(shí)，我們可以初步確認(rèn)：當(dāng)前的性能問(wèn)題和相關(guān)的SQL執(zhí)行并沒(méi)有直接聯(lián)系，很大概率是ORACLE的內(nèi)部運(yùn)行機(jī)制出現(xiàn)問(wèn)題，即可能是BUG的問(wèn)題!
我們通過(guò)METALINK發(fā)現(xiàn)該問(wèn)題進(jìn)一步確認(rèn)是BUG方面的問(wèn)題，如下：
注：具體見METALINK DOC ID：1162566.1
從上面的信息我們發(fā)現(xiàn)，當(dāng)前系統(tǒng)問(wèn)題與BUG 9776608有一定的符合性：
當(dāng)前版本都是11.2.0.0.1
出現(xiàn)大量row cache lock，而且都是短的大量的row cache lock等待。
通過(guò)進(jìn)一步分析系統(tǒng)底層調(diào)用都是ksedsts()+644<- ksdxfstk() +44<- ksdxcb()……等函數(shù)開頭。
根據(jù)文檔要求，該問(wèn)題可升級(jí)到11.2.0.2以上版本或安裝補(bǔ)丁包patch9776608解決問(wèn)題。
隨后，我們配合運(yùn)維人員進(jìn)行系統(tǒng)ORACLE數(shù)據(jù)庫(kù)基于PSU補(bǔ)丁升級(jí)：
考慮到當(dāng)前系統(tǒng)最新版本，我們直接把數(shù)據(jù)庫(kù)升級(jí)到11.2.0.3.4版本。
考慮到系統(tǒng)升級(jí)的安全性，我們先對(duì)測(cè)試環(huán)境進(jìn)行PSU補(bǔ)丁的升級(jí)，然后再對(duì)正式環(huán)境進(jìn)行升級(jí)。
完成升級(jí)后，對(duì)系統(tǒng)進(jìn)行監(jiān)控，確認(rèn)性能問(wèn)題得到徹底解決!
附錄：?jiǎn)栴}解決后前后性能對(duì)比解釋
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)相對(duì)壓力比較大的時(shí)間段1小時(shí)的工作日志，DBTIME 只運(yùn)行 59分鐘，為存在性能問(wèn)題時(shí)間段(之前同一時(shí)間段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
在整個(gè)系統(tǒng)時(shí)間模型中，解釋的時(shí)間僅占到數(shù)據(jù)庫(kù)運(yùn)行時(shí)間的6.16%，比之前的80%以上下降了75%以上。
申請(qǐng)創(chuàng)業(yè)報(bào)道，分享創(chuàng)業(yè)好點(diǎn)子。點(diǎn)擊此處，共同探討創(chuàng)業(yè)新機(jī)遇！
