NDMCDB資料庫hang住故障分析
問題描述:
上午剛剛到辦公室,就有監控人員郵件反饋,昨晚NDMCDB407資料庫被重啟過,讓我分析一下資料庫重啟的原因。由於昨晚業務有版本上線,所以簡訊警告關閉了,所以沒有簡訊下發到我手機上,而且故障時相關人員也沒有通知到我。
1 檢查alert日誌
從alert日誌中,可以看到,先是在03:29時有一個job執行失敗了: Fri Aug 22 03:29:29 2014 Errors in file/opt/oracle/diag/rdbms/ndmcdb/NDMCDB/trace/NDMCDB_j000_28856.trc: ORA-12012: error on auto execute of job 31 ORA-04023: ObjectNDMC.DELETE_ANONY_RSHARE_INFO could not be validated or authorized ORA-06512: at "NDMC.PROC_NDMC_CANCEL_OPEN",line 5 ORA-06512: at line 1 然後在03:49時,出現了連線超時失敗,而且一直持續到05:00:08: Fri Aug 22 03:49:43 2014 *********************************************************************** Fatal NI connect error 12170. VERSION INFORMATION: TNS for Linux: Version 11.1.0.7.0 - Production Oracle Bequeath NT Protocol Adapter for Linux: Version 11.1.0.7.0 -Production TCP/IP NT Protocol Adapter for Linux: Version 11.1.0.7.0 - Production Time: 22-AUG-2014 03:49:43 Tracing not turned on. Tnserror struct: ns main err code: 12535 TNS-12535: TNS:operation timed out ns secondary err code: 12606 nt main err code: 0 nt secondary err code: 0 nt OS err code: 0 Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.130.87)(PORT=36628)) WARNING: inbound connection timed out(ORA-3136) Fri Aug 22 03:49:44 2014 …… 而且出現了連線數耗盡了: Fri Aug 22 03:49:50 2014 ORA-00020: maximum number of processes 0exceeded ns secondary err code: 12560 ns secondary err code: 12560 ns main err code: 12537 Fri Aug 22 03:49:50 2014 …… Fri Aug 22 03:51:48 2014 *********************************************************************** Fatal NI connect error 12537, connectingto: (LOCAL=NO) VERSION INFORMATION: TNS for Linux: Version 11.1.0.7.0 - Production Oracle Bequeath NT Protocol Adapter for Linux: Version 11.1.0.7.0 -Production TCP/IP NT Protocol Adapter for Linux: Version 11.1.0.7.0 - Production Time: 22-AUG-2014 03:51:48 Tracing not turned on. Tnserror struct: ns main err code: 12537 TNS-12537: TNS:connection closed ns secondaryerr code: 12560 nt main err code: 0 nt secondary err code: 0 nt OS err code: 0 ORA-609 : opiodr aborting process unknownospid (30476_47044991385184) Fri Aug 22 04:14:15 2014 ORA-28 : opiodr aborting process unknownospid (24925_46986315964000) Fri Aug 22 04:16:27 2014 ORA-28 : opiodr aborting process unknownospid (22475_47013891882592) Fri Aug 22 04:16:28 2014 ORA-28 : opiodr aborting process unknownospid (21356_47116835528288) Fri Aug 22 04:16:29 2014 ORA-28 : opiodr aborting process unknownospid (24947_47774766210656) ORA-28 : opiodr aborting process unknownospid (14958_47053435166304) …… Fri Aug 22 05:00:05 2014 ORA-28 : opiodr aborting process unknownospid (25765_46941307182688) Fri Aug 22 05:00:08 2014 ORA-28 : opiodr aborting process unknownospid (4949_47396524895840) 於是在05:04資料庫被關閉,從日誌來看,這是正常關閉的,初步懷疑是人為關閉或是VCS雙機自動將資料庫關閉了: Fri Aug 22 05:04:10 2014 Stopping background process SMCO Stopping background process FBDA Shutting down instance: further logonsdisabled Fri Aug 22 05:04:12 2014 Stopping background process CJQ0 Stopping background process QMNC Stopping background process MMNL Stopping background process MMON Shutting down instance (immediate) License high water mark = 1220 Stopping Job queue slave processes, flags =7 Fri Aug 22 05:04:20 2014 Waiting for Job queue slaves to complete Job queue slave processes stopped Fri Aug 22 05:09:11 2014 License high water mark = 1220 USER (ospid: 25110): terminating theinstance Termination issued to instance processes.Waiting for the processes to exit Fri Aug 22 05:09:21 2014 Instance termination failed to kill one ormore processes Instance terminated by USER, pid = 25110
2 檢查messages日誌
大概在05:03:51時,人為的想將雙機切換到備機中:
Aug 22 05:03:51 NDMCDB11 user_cmd:2014-08-22 05:03:51 hagrp -switch RCS_DB_SG -to system by root from [oraclepts/9 Aug 22 04:29 (192.168.128.142)] Aug 22 05:04:01 NDMCDB11/usr/sbin/cron[15348]: (root) CMD (su - root -c'/opt/watchdog/watchdog_schedule -n OS,oracle' >/dev/null 2>&1) Aug 22 05:04:01 NDMCDB11 su: (to root) rooton none Aug 22 05:04:03 NDMCDB11 su: (to oracle)root on none Aug 22 05:04:09 NDMCDB11 user_cmd:2014-08-22 05:04:09 hagrp -switch RCS_DB_SG -to NDMCDB12 by root from [oraclepts/9 Aug 22 04:29 (192.168.128.142)] Aug 22 05:04:09 NDMCDB11 su: (to oracle)root on none
但雙機切換失敗,最後是直接將雙機停止,重啟VCS:
Aug 22 05:06:18 NDMCDB11 user_cmd:2014-08-22 05:06:18 hastop -all by root from [oracle pts/9 Aug 22 04:29(192.168.128.142)]
……
Aug 22 05:07:02 NDMCDB11 user_cmd:2014-08-22 05:07:02 hastat by root from [oracle pts/9 Aug 22 04:29(192.168.128.142)]
所以,到這裡就已經確定,資料庫這所以重啟了,完全是由於人為將VCS叢集重啟引起的。那麼為什麼要VCS群集重啟呢?資料庫到底有沒有問題呢?再來看看。
最後,經向升級人員操作確認,在升級時,有一個儲存過程需要跑,但執行後,資料庫基本響應就非常慢了,一直執行到3:29左右,人為cancel掉了,所以這也就是為什麼會出現這樣的報錯了:
Fri Aug 22 03:29:29 2014
Errors in file/opt/oracle/diag/rdbms/ndmcdb/NDMCDB/trace/NDMCDB_j000_28856.trc:
ORA-12012: error on auto execute of job 31
ORA-04023: ObjectNDMC.DELETE_ANONY_RSHARE_INFO could not be validated or authorized
ORA-06512: at"NDMC.PROC_NDMC_CANCEL_OPEN", line 5
ORA-06512: at line 1
3 檢視系統負載
CPU負載:
記憶體負載:
可見,系統在3:49左右,出現了CPU及記憶體均被耗盡的情況,這個時間段,剛好資料庫出現了大量連線超時失敗,甚至是出現了連線數超過閥值:
Fri Aug 22 03:49:50 2014
ORA-00020: maximum number of processes 0exceeded
ns secondary err code: 12560
ns secondary err code: 12560
ns main err code: 12537
Fri Aug 22 03:49:50 2014
4 分析AWR
從這裡看,資料庫在2點到3點時,已經非常的繁忙,但從之前有系統負載來看,2點到3點時,CPU及記憶體使用率都不算很高的。接著看:
指標都沒有什麼特別高的。
從top 5 event中,看到了有大量的cursor: pin S wait on X等待,可見出現mutex爭用,但通常這只是表象而已,並非根因。
絕大部分時間都在做SQL的解析,而且解析還失敗了,這就是資料庫hang住的根因。正常來說,一個數據庫的絕大部分時間應該是用於SQL的執行,所以這個是佔用最多時間的:sql execute elapsedtime等。
不存在較高的versioncount。
那麼資料庫什麼時候出現的不停解析SQL,並且解析失敗了呢?
查了DBA_HIST_ACTIVE_SESS_HISTORY,分析了下歷史會話資訊,發現在02:57:00至03:00:00出現的問題:
經過確認,恰巧就是執行儲存過程的時間點左右。
至此,資料庫從3:00開始,已經是不正常的,資料庫不停的在解析SQL,SQL都還沒有到執行這一步,資料庫已經處於無響應的狀態,連線會話都被阻塞住了,直到連線數達到了最大連線數,最後被升級操作人員重啟了VCS叢集。
5 分析結論
(1)資料庫down機主要還是人為進行了VCS切換失敗後,進行了VCS重啟操作引起。
(2)這套資料庫故障的根因,還是為什麼資料庫在2:58左右時出現解析SQL失敗上。從目前的日誌分析來看,看不出是什麼原因。
-- Bosco ---- END -----------------------------------------------------------------------------------------------------------
版權所有,文章允許轉載,但必須以連結方式註明源地址,否則追究法律責任!