從業務角度分析奇怪的資料庫高負載問題

jeanron100發表於2015-02-03

今天到公司以後,照例檢視了資料庫的負載情況,發現有一些異常。11點開始到12點的時候,資料庫的負載格外的高。按照平時的經驗,這個時間段內不會有太多的高峰業務在執行,為了簡單驗證,自己抓取了近幾天的資料庫負載情況。
自己抓取了2月1號,1月30號的負載情況,發現在這個時間段內資料庫的負載其實不高。
snap_begin snap_end start_time level duration(mins) DB time(mins)
30775 30776 3 Feb 2015 10:50 1 10 875
30776 30777 3 Feb 2015 11:00 1 10 1203
30777 30778 3 Feb 2015 11:10 1 10 1176
30778 30779 3 Feb 2015 11:20 1 10 1202
30779 30780 3 Feb 2015 11:30 1 10 1152
30780 30781 3 Feb 2015 11:40 1 10 1313
30781 30782 3 Feb 2015 11:50 1 10 1401
30782 30783 3 Feb 2015 12:00 1 10 1089
30783 30784 3 Feb 2015 12:10 1 10 1124
30784 30785 3 Feb 2015 12:20 1 10 1195
30785 30786 3 Feb 2015 12:30 1 10 1118
30786 30787 3 Feb 2015 12:40 1 10 1083
30787 30788 3 Feb 2015 12:50 1 10 980
30788 30789 3 Feb 2015 13:00 1 10 968
30789 30790 3 Feb 2015 13:10 1 10 860
30790 30791 3 Feb 2015 13:20 1 10 758
30791 30792 3 Feb 2015 13:30 1 10 736
30792 30793 3 Feb 2015 13:40 1 10 655
30793 30794 3 Feb 2015 13:50 1 10 489
30794 30795 3 Feb 2015 14:00 1 10 571
30795 30796 3 Feb 2015 14:10 1 10 576
30796 30797 3 Feb 2015 14:20 1 10 687
30797 30798 3 Feb 2015 14:30 1 10 727
30798 30799 3 Feb 2015 14:40 1 10 550
30799 30800 3 Feb 2015 14:50 1 10 648
                 
30487 30488 1 Feb 2015 10:50 1 10 312
30488 30489 1 Feb 2015 11:00 1 10 489
30489 30490 1 Feb 2015 11:10 1 10 429
30490 30491 1 Feb 2015 11:20 1 10 311
30491 30492 1 Feb 2015 11:30 1 10 331
30492 30493 1 Feb 2015 11:40 1 10 288
30493 30494 1 Feb 2015 11:50 1 10 221
30494 30495 1 Feb 2015 12:00 1 10 335
30495 30496 1 Feb 2015 12:10 1 10 530
30496 30497 1 Feb 2015 12:20 1 10 430
30497 30498 1 Feb 2015 12:30 1 10 366
30498 30499 1 Feb 2015 12:40 1 10 370
30499 30500 1 Feb 2015 12:50 1 10 288
30500 30501 1 Feb 2015 13:00 1 10 286
30501 30502 1 Feb 2015 13:10 1 10 283
30502 30503 1 Feb 2015 13:20 1 10 193
30503 30504 1 Feb 2015 13:30 1 10 215
30504 30505 1 Feb 2015 13:40 1 10 205
30505 30506 1 Feb 2015 13:50 1 10 200
30506 30507 1 Feb 2015 14:00 1 10 239
30507 30508 1 Feb 2015 14:10 1 10 202
30508 30509 1 Feb 2015 14:20 1 10 175
30509 30510 1 Feb 2015 14:30 1 10 229
30510 30511 1 Feb 2015 14:40 1 10 226
30511 30512 1 Feb 2015 14:50 1 10 216
30199 30200 30 Jan 2015 10:50 1 10 377
30200 30201 30 Jan 2015 11:00 1 10 572
30201 30202 30 Jan 2015 11:11 1 10 428
30202 30203 30 Jan 2015 11:20 1 9 664
30203 30204 30 Jan 2015 11:30 1 10 580
30204 30205 30 Jan 2015 11:40 1 10 409
30205 30206 30 Jan 2015 11:50 1 10 277
30206 30207 30 Jan 2015 12:00 1 10 464
30207 30208 30 Jan 2015 12:10 1 10 365
30208 30209 30 Jan 2015 12:20 1 10 333
30209 30210 30 Jan 2015 12:30 1 10 315
30210 30211 30 Jan 2015 12:40 1 10 355
30211 30212 30 Jan 2015 12:50 1 10 304
30212 30213 30 Jan 2015 13:00 1 10 287
30213 30214 30 Jan 2015 13:10 1 10 234
30214 30215 30 Jan 2015 13:20 1 10 255
30215 30216 30 Jan 2015 13:30 1 10 321
30216 30217 30 Jan 2015 13:40 1 10 329
30217 30218 30 Jan 2015 13:50 1 10 273
30218 30219 30 Jan 2015 14:00 1 10 398
30219 30220 30 Jan 2015 14:10 1 10 347
30220 30221 30 Jan 2015 14:20 1 10 363
30221 30222 30 Jan 2015 14:30 1 10 511
30222 30223 30 Jan 2015 14:40 1 10 527
30223 30224 30 Jan 2015 14:50 1 10 356

從客戶那裡瞭解的情況是,他們昨天晚上對系統打了補丁,但是沒有修改其它的地方。
為了查詢問題,我抓取了問題時間段內的awr報告。
得到的等待事件情況如下:

Top 5 Timed Foreground Events

Event Waits Time(s) Avg wait (ms) % DB time Wait Class
direct path read 757,842 25,844 34 36.61 User I/O
db file sequential read 6,253,924 24,112 4 34.16 User I/O
DB CPU   8,433   11.95  
read by other session 1,736,151 5,387 3 7.63 User I/O
log file sync 98,407 2,715 28 3.85 Commit


可以看到等待時間都是和IO緊密相關的。從等待事件direct path read來看,我的一個直觀感覺就是並行查詢導致的。
使用並行掃描的SQL語句也會影響系統範圍的direct path read等待事件。在並行執行過程中,direct path read等待事件與從屬查詢有關,而與父查詢無關,執行父查詢的會話基本上會在PX Deq:Execute Reply上等待,從屬查詢會產生direct path read等待事件。
從SQL Order by Elapsed time這個章節,可以看到幾個消耗很大的語句都和一個信控相關的掃描服務相關。
Elapsed Time (s) Executions Elapsed Time per Exec (s) %Total %CPU %IO SQL Id SQL Module SQL Text
14,326.71 24 596.95 20.30 8.58 89.48 JDBC Thin Client /* ProcInstScanner_selectAv...
10,674.05 23 464.09 15.12 6.01 92.01 JDBC Thin Client /* WaitScanner_selectWorkab...
5,641.97 24 235.08 7.99 6.90 93.09 JDBC Thin Client select /*+ leading (bpm_ai bpm...
1,628.99 5 325.80 2.31 2.85 98.39 JDBC Thin Client select /*+ leading(s) index(s ...

這幾個服務的啟動時間大概是在10點左右,但是今天卻在11點多開始對資料庫有相當的壓力。當時也沒多想,繼續檢視並行的部分來驗證direct path read的想法。
結果在並行的部分發現了一些問題。
下面標黃的部分是weblogic節點的連線使用者,按照規律來看都是truwlxxx的樣式,但是今天看到是確實truwld5,truwld4這種型別的。這個問題沒有做過多的確認,但是感覺已經是個問題了。
和最近的系統升級聯絡起來,最近在生產庫中加入了一些weblogic節點來分擔一部分的業務壓力,但是據我所知,這些新加入的節點都是不需要開啟信控服務的。

SESS_ID         USERNAME        OSUSER          MACHINE              PROGRAM                        QCSID       SQL_ID 
------------------------------------------------------------------------------------------------------------------------------------
3787,15127      PRDAPPC         truwld5         ccbpr13            JDBC Thin Client                3787            4gz51fphuarsw
5199,3205       PRDAPPC         pblwrk01        ccbpr1             bl1b@ccbdbpr1 (TNS V1- V3)   5199            cjfjyu20nhaws                                                                    
9198,11215      PRDAPPC         pcmwrk01        ccbpr1             JDBC Thin Client                9198            9s6vg5rnupjv9
18629,16045     PRDAPPC         truwld5         ccbpr13            JDBC Thin Client                18629            6fu3z8pqd2y9g
13255,52127     PRDAPPC         pblwrk01        ccbpr1             sqlplus@ccbdbpr1 (TNS V1- V3)   13255            55u2k96k7bx91
3053,36995      PRDAPPC         pcmwrk01        ccbpr1             JDBC Thin Client                3053            cq7p84hrug0wx
18716,785       PRDAPPC         truwld4         ccbpr13            JDBC Thin Client                18716            4gz51fphuarsw
1753,1793       PRDAPPC         truwl25         ccbpr2             JDBC Thin Client                1753            4gz51fphuarsw
7478,19407      CCBSFMDEV       Phongs4         TIT-C25            plsqldev.exe                    7478
4792,5385       PRDAPPC         truwld2         ccbpr13            JDBC Thin Client                4792            4gz51fphuarsw
帶著這種半信半疑,還是給客戶傳送了郵件,讓他們確認一下,是否開啟了新加的weblogic節點的信控服務,他們在查詢之後最後反饋,確實是啟用了這些服務,馬上做了禁用操作。
系統負載馬上就降下來了。最後客戶對相關的節點都做了檢驗,從我的監控來看,再也沒有捕捉到新節點的並行程式。問題的處理就告一段落了。
從這個問題的分析來看,有幾個關鍵的注意點,首先從負載上來看可能存在著問題,但是單純從負載來看也不能說明問題,需要自己對系統的業務情況進行一個基本的瞭解,這樣在分析問題的時候才能更加的準備到位,可以自己沉澱一些監控的資料,在問題發生之後及時做比對,就很能夠說明一些看似複雜的問題。
這個問題的分析結果也是在瞭解了近期的系統變更上,自己瞭解了信控服務的特點,所以在分析問題的時候按照這個基準來驗證新加入的節點可能有問題。然後逐步分析驗證了自己的推論。這個時候如果單純從技術角度來看,可能這些並行程式的執行還真不是問題,很可能看做是業務需要,導致分析到最後可能在sql調優上反覆下很多的功夫,最後發現調優的工作已經很難有改進空間了,導致問題方向性的錯誤。
最後一個就是敢於質疑,如果你的推論正確了,就可以避免一次不必要的系統問題,如果你的推論錯了,可能還需要從其他的角度來分析這些問題,對自己也沒有什麼害處,切忌不要抱著抓到客戶小辮子的態度,這樣客戶也會顯得不夠配合。

來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/23718752/viewspace-1425624/,如需轉載,請註明出處,否則將追究法律責任。

相關文章