從業務角度分析奇怪的資料庫高負載問題
今天到公司以後，照例檢視了資料庫的負載情況，發現有一些異常。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/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- 從資料庫角度談業務連續性資料庫
- Flume高可用負載均衡問題負載
- 黃牛是怎樣搶票的？——從業務分析師角度看買票難問題
- 執行計劃變化導致CPU負載高的問題分析負載
- 資料庫連線沒有釋放造成的奇怪問題資料庫
- 使用strace分析exp的奇怪問題
- 從“物件”的角度，帶你分析資料型別物件資料型別
- 網易資料分析業務題
- 資料庫高io問題調查資料庫
- ORACLE資料檔名導致的奇怪問題Oracle
- 資料庫11g升級中一次奇怪的問題資料庫
- 資料庫高回滾爭用的問題資料庫
- 從Oracle資料庫管理員的角度看PostgreSQLOracle資料庫SQL
- openGauss資料庫分析問題資料庫
- 資料庫索引分裂 問題分析資料庫索引
- 奇怪的問題： 資料庫使用者登入的時候報錯資料庫
- 解決Oracle資料庫遷移後的伺服器負載效能問題JSOracle資料庫伺服器負載JS
- 一個高請求量負載設計問題負載
- 新系統上線，10G 資料庫負載持續高資料庫負載
- MVCC缺陷與高負載PG資料庫最佳化要點MVC負載資料庫
- 高併發高負載情況下常見的3種效能問題負載
- 一則資料庫無法啟動的奇怪案例分析資料庫
- 資料庫突然當機的問題及分析資料庫
- 深度分析資料庫的熱點塊問題資料庫
- linux高負載下mysql資料庫徹底最佳化(轉)Linux負載MySql資料庫
- 關於desc的一個奇怪問題及分析
- 一個負載均衡的問題負載
- 從原始碼角度分析SrcollView巢狀ListView顯示不全的問題原始碼View巢狀
- 資料庫Server效能問題分析案例一資料庫Server
- 深度分析資料庫的熱點塊問題(轉)資料庫
- 分析發生在過去的資料庫效能問題資料庫
- 一次資料庫當機問題的分析資料庫
- 深度分析資料庫的熱點塊問題 (zt)資料庫
- Mycat 雙主雙從-負載均衡-高可用負載
- Oracle 11g 資料庫伺服器CPU、IO負載高的故障排除流程Oracle資料庫伺服器負載
- 解決資料庫高併發訪問瓶頸問題資料庫
- 從運維角度淺談 MySQL 資料庫優化運維MySql資料庫優化
- ORACLE 資料庫11.2.0.4 單例項伺服器IO等待高問題分析Oracle資料庫單例伺服器