OLM·BUG原因引發(fā)的性能故障分析與處理案例

導(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ō)到性能問題,我們都是聯(lián)想到是否SQL執(zhí)行出現(xiàn)了性能問題?是否配置不合理?是否CPU和IO等操作系統(tǒng)資源使用出現(xiàn)問題?但最近我們遇到了一個(gè)由于ORACLE BUG引發(fā)的數(shù)據(jù)庫(kù)性能問題。

背景:用戶反饋有一套系統(tǒng)運(yùn)行很慢,包括所有的操作如一般的登錄、查詢、編輯、報(bào)表輸出都突然變得很慢,開發(fā)人員和運(yùn)維人員都做了相關(guān)的檢查和一般分析,但都沒發(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)一下整體上的性能問題,整體數(shù)據(jù)庫(kù)時(shí)間消耗如下:


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分鐘的報(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ù)整體上性能問題,并判斷可能是鎖(包括lock鎖和Latch鎖)資源等待問題,然后進(jìn)一步看等待事件:

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ù)后臺(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 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í)間模型數(shù)據(jù),可以看到60分鐘之內(nèi),用于SQL或PLSQL解釋的時(shí)間就占了80%以上,即25552秒,我們可以推測(cè)出由于與共享池相關(guān)的row cache lock等待事件導(dǎo)致了SQL解釋出現(xiàn)問題,并最終大量的SQL運(yùn)行變成緩慢,從于引發(fā)了系統(tǒng)的整體上性問題。

根據(jù)上面的分析數(shù)據(jù),我們第一步就是先確認(rèn)數(shù)據(jù)庫(kù)配置是否存在問題,對(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)提升,可沒從實(shí)質(zhì)上解決整體上系統(tǒng)慢的性能問題。

我們繼續(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)前的性能問題和相關(guān)的SQL執(zhí)行并沒有直接聯(lián)系,很大概率是ORACLE的內(nèi)部運(yùn)行機(jī)制出現(xiàn)問題,即可能是BUG的問題!

我們通過(guò)METALINK發(fā)現(xiàn)該問題進(jìn)一步確認(rè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等待。

  • 通過(guò)進(jìn)一步分析系統(tǒng)底層調(diào)用都是ksedsts()+644<- ksdxfstk() +44<- ksdxcb()……等函數(shù)開頭。

根據(jù)文檔要求,該問題可升級(jí)到11.2.0.2以上版本或安裝補(bǔ)丁包patch9776608解決問題。

隨后,我們配合運(yùn)維人員進(jìn)行系統(tǒng)ORACLE數(shù)據(jù)庫(kù)基于PSU補(bǔ)丁升級(jí):

  1. 考慮到當(dāng)前系統(tǒng)最新版本,我們直接把數(shù)據(jù)庫(kù)升級(jí)到11.2.0.3.4版本。

  2. 考慮到系統(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)性能問題得到徹底解決!

附錄:?jiǎn)栴}解決后前后性能對(duì)比解釋

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)相對(duì)壓力比較大的時(shí)間段1小時(shí)的工作日志,DBTIME 只運(yùn)行 59分鐘,為存在性能問題時(shí)間段(之前同一時(shí)間段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

在整個(gè)系統(tǒng)時(shí)間模型中,解釋的時(shí)間僅占到數(shù)據(jù)庫(kù)運(yùn)行時(shí)間的6.16%,比之前的80%以上下降了75%以上。

極客網(wǎng)企業(yè)會(huì)員

免責(zé)聲明:本網(wǎng)站內(nèi)容主要來(lái)自原創(chuàng)、合作伙伴供稿和第三方自媒體作者投稿,凡在本網(wǎng)站出現(xiàn)的信息,均僅供參考。本網(wǎng)站將盡力確保所提供信息的準(zhǔn)確性及可靠性,但不保證有關(guān)資料的準(zhǔn)確性及可靠性,讀者在使用前請(qǐng)進(jìn)一步核實(shí),并對(duì)任何自主決定的行為負(fù)責(zé)。本網(wǎng)站對(duì)有關(guān)資料所引致的錯(cuò)誤、不確或遺漏,概不負(fù)任何法律責(zé)任。任何單位或個(gè)人認(rèn)為本網(wǎng)站中的網(wǎng)頁(yè)或鏈接內(nèi)容可能涉嫌侵犯其知識(shí)產(chǎn)權(quán)或存在不實(shí)內(nèi)容時(shí),應(yīng)及時(shí)向本網(wǎng)站提出書面權(quán)利通知或不實(shí)情況說(shuō)明,并提供身份證明、權(quán)屬證明及詳細(xì)侵權(quán)或不實(shí)情況證明。本網(wǎng)站在收到上述法律文件后,將會(huì)依法盡快聯(lián)系相關(guān)文章源頭核實(shí),溝通刪除相關(guān)內(nèi)容或斷開相關(guān)鏈接。

2017-09-25
OLM·BUG原因引發(fā)的性能故障分析與處理案例
導(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ō)到性能問題,我們都是聯(lián)想到是否SQL執(zhí)行出現(xiàn)

長(zhǎng)按掃碼 閱讀全文