一次資料庫宕機問題的分析(r6筆記第5天)
今天來到辦公室,發現有一臺伺服器中的資料庫例項停掉了。這種情況真是意料之外,尤其是我還不是很熟悉這臺機器的服務。 趕緊檢視資料庫日誌,可以看到資料庫在昨晚停掉了,從日誌來看沒有人為的痕跡。 在宕機之前,有下面的日誌。在此擷取一部分。
TNS-12560: TNS:protocol adapter error opiodr aborting process unknown ospid (33498) as a result of ORA-609 ns secondary err code: 0 nt main err code: 0 nt secondary err code: 0 nt OS err code: 0 opiodr aborting process unknown ospid (33500) as a result of ORA-609 opiodr aborting process unknown ospid (33496) as a result of ORA-609 Tue Jul 21 23:08:18 2015 Errors in file /U01/app/oracle/diag/rdbms/xxxx/xxxx/trace/xxxx_smco_7609.trc (incident=56361): ORA-00445: background process "W001" did not start after 120 seconds Incident details in: /U01/app/oracle/diag/rdbms/xxxx/xxxx/incident/incdir_56361/xxxx_smco_7609_i56361.trc Tue Jul 21 23:09:17 2015 Dumping diagnostic data in directory=[cdmp_20150721230917], requested by (instance=1, osid=7609 (SMCO)), summary=[incident=56361]. Tue Jul 21 23:09:19 2015 Sweep [inc][56361]: completed Sweep [inc2][56361]: completed opiodr aborting process unknown ospid (35054) as a result of ORA-609 opiodr aborting process unknown ospid (35052) as a result of ORA-609 Tue Jul 21 23:16:38 2015 Active Session History (ASH) performed an emergency flush. This may mean that ASH is undersized. If emergency flushes are a recurring issue, you may consider increasing ASH size by setting the value of _ASH_SIZE to a sufficiently large value. Currently, ASH size is 50331648 bytes. Both ASH size and the total number of emergency flushes since instance startup can be monitored by running the following query: select total_size,awr_flush_emergency_count from v$ash_info; Tue Jul 21 23:18:43 2015 Process RSM0, PID = 35012, will be killed Tue Jul 21 23:18:45 2015 RSM0 started with pid=640, OS id=35799 Tue Jul 21 23:22:06 2015 Process m000 died, see its trace file Tue Jul 21 23:22:06 2015 Tue Jul 21 23:31:23 2015 Errors in file /U01/app/oracle/diag/rdbms/xxxx/xxxx/trace/xxxx_mmon_4651.trc (incident=56137): ORA-00445: background process "m000" did not start after 120 seconds Incident details in: /U01/app/oracle/diag/rdbms/xxxx/xxxx/incident/incdir_56137/xxxx_mmon_4651_i56137.trc Tue Jul 21 23:31:24 2015 Wed Jul 22 00:22:39 2015 Process RSM0, PID = 42798, will be killed Wed Jul 22 00:22:52 2015 Errors in file /U01/app/oracle/diag/rdbms/xxxxx/xxxxx/trace/xxxxx_m000_43079.trc: ORA-12751: cpu time or run time policy violation Wed Jul 22 00:22:53 2015 RSM0 started with pid=39, OS id=44965 Wed Jul 22 00:24:07 2015 Thread 1 advanced to log sequence 46159 (LGWR switch) Current log# 3 seq# 46159 mem# 0: /U01/app/oracle/oradata/xxxxx/redo03.log Wed Jul 22 00:24:10 2015 LNS: Standby redo logfile selected for thread 1 sequence 46159 for destination LOG_ARCHIVE_DEST_2 Wed Jul 22 00:30:48 2015 WARN: ARC2: Terminating pid 5636 hung on an I/O operation Wed Jul 22 00:31:18 2015 krsv_proc_kill: Killing 1 processes (Process by index) Wed Jul 22 00:32:18 2015 ARC2: Error 16198 due to hung I/O operation to LOG_ARCHIVE_DEST_1 Wed Jul 22 00:36:01 2015 Sweep [inc][56137]: completed ARC3: Archival started ARC2: STARTING ARCH PROCESSES COMPLETE ARCH: Archival stopped, error occurred. Will continue retrying ORACLE Instance xxxxx- Archival Error ORA-16014: log 2 sequence# 46158 not archived, no available destinations
從日誌來看,資料庫的錯誤型別很多。看起來似乎網路,CPU,IO都佔到了。 帶著疑問趕緊和同事進行了確認。最後同事建議先看看主庫能不能open。如果不可以只能switchover了。 自己開始嘗試啟庫,nomount,mount,檢查了引數檔案,控制檔案的情況。 從v$backup中排除了相關熱備份的干擾。資料檔案的scn和資料庫級都是相同的。 最後嘗試open,在短暫緊張的等待之後,資料庫是順利起來了。 然後開始分析這個問題的原因。首先從直觀感覺來看,伺服器的反應很慢,iowait很高。
top - 09:40:05 up 22 days, 12:03, 3 users, load average: 38.33, 24.68, 11.11 Tasks: 824 total, 1 running, 820 sleeping, 0 stopped, 3 zombie Cpu(s): 1.0%us, 0.8%sy, 0.0%ni, 80.8%id, 17.4%wa, 0.0%hi, 0.0%si, 0.0%st Mem: 132110448k total, 105395236k used, 26715212k free, 784000k buffers Swap: 16777200k total, 0k used, 16777200k free, 2847488k cached
有時候使用sqlplus或者使用linux命令都會卡住。 來看看io的情況。
$ iostat -x 2 Linux 2.6.32-279.el6.x86_64 (xxxxxx) 07/22/2015 _x86_64_ (24 CPU) avg-cpu: %user %nice %system %iowait %steal %idle 1.81 0.00 0.12 0.84 0.00 97.23 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util sda 0.05 1.13 7.00 3.22 1375.40 161.00 150.34 0.08 7.87 0.74 0.76 sdb 7.35 3.28 235.05 187.89 50660.90 6300.31 134.68 1.61 3.80 0.38 15.92 avg-cpu: %user %nice %system %iowait %steal %idle 1.57 0.00 0.48 17.24 0.00 80.71 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util sda 0.00 13.00 36.00 5.50 9072.00 148.00 222.17 0.11 2.57 0.78 3.25 sdb 1847.50 17.00 2245.50 11.00 1031796.00 256.50 457.37 73.46 30.51 0.44 100.00 avg-cpu: %user %nice %system %iowait %steal %idle 1.13 0.00 0.40 20.01 0.00 78.47 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sdb 1836.00 0.00 2154.50 0.00 1016752.00 0.00 471.92 72.99 30.49 0.46 100.00
可以看到sdb盤在進行大量的讀操作,%util的比例已經達到100% 可以從兩個盤的讀寫上進行比較。
$ iostat 2
Linux 2.6.32-279.el6.x86_64 (tlbb3dbidb.cyou.com) 07/22/2015 _x86_64_ (24 CPU)
avg-cpu: %user %nice %system %iowait %steal %idle
1.81 0.00 0.12 0.84 0.00 97.23
Device: tps Blk_read/s Blk_wrtn/s Blk_read Blk_wrtn
sda 10.22 1375.37 161.00 2675007527 313127700
sdb 422.99 50692.01 6300.10 98592909044 12253317633
avg-cpu: %user %nice %system %iowait %steal %idle
3.52 0.00 0.52 18.23 0.00 77.73
Device: tps Blk_read/s Blk_wrtn/s Blk_read Blk_wrtn
sda 10.00 0.00 128.00 0 256
sdb 2039.50 974104.00 0.00 1948208 0
avg-cpu: %user %nice %system %iowait %steal %idle
1.17 0.00 0.38 20.31 0.00 78.15
Device: tps Blk_read/s Blk_wrtn/s Blk_read Blk_wrtn
sda 0.00 0.00 0.00 0 0
sdb 2022.00 973192.00 0.00 1946384 0
可以看到在CPU利用率不怎麼高的前提下,sdb盤在進行滿負荷的讀。
通過/etc/fstab中可以看到這個盤對應的分割槽就是存放資料檔案的分割槽。
/dev/sdb /U01 ext4 defaults 1 2
初步懷疑是不是硬碟出問題了,在同事的幫助下使用megaCli查看了硬碟的情況,沒有發現任何的壞塊。
所以從物理上來說硬碟到目前為止沒有發現問題。
這個時候我們可以結合日誌進行一些分析,但是大部分日誌都是昨晚的了,而且目前的問題時,資料庫已經啟動起來了,但是還是比較慢。這個時候這種問題真是雪上加霜。
不過還是靜下心來認真做分析吧,排除了硬碟,檢視是否可能是cpu,當然這個可以作為一個檢查點,很快就可以排除。
$ ksh cpuinfo.sh
**************************************
CPU Physical NO: 2
CPU Processor NO: 24
CPU Core NO: cpu cores : 6
CPU model name : Intel(R) Xeon(R) CPU E5-2620 0 @ 2.00GHz
**************************************
可以看出CPU沒有問題,因為聽說之前出過CPU相關的問題。 這個時候還是從top來看比較直觀。能從top中看到有一些客戶端的session相關的程序佔用的CPU達到了100%,IO佔用也很高。 這也是一個疑點。我們可以繫結作業系統程序得到session的一些詳細資訊來參考。 繫結作業系統程序的過程參加 http://blog.itpub.net/23718752/viewspace-1424376/ 可以抓取到其中一個session在做一個簡單的查詢。
SQL_ID SQL_TEXT
------------------------------ ------------------------------------------------------------
db6tf3qs75pvu SELECT appkey,:1,'xxxx',count(distinct t.userid),2,3 FROM
m_xxxx_log t WHERE appkey in ('xxxxxx','14
xxxxx') and t.time >= to_date(:2, 'yyyy-mm-dd HH24:mi:
ss') AND t.time < to_date(:3, 'yyyy-mm-dd HH24:mi:ss')
group by appkey
語句還是比較簡單的。 但是執行計劃卻有問題。
Plan hash value: 2105531167
------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | Pstart| Pstop |
------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 168K(100)| | | |
| 1 | HASH GROUP BY | | 2 | 288 | 168K (1)| 00:33:45 | | |
| 2 | VIEW | VM_NWVW_1 | 12 | 1728 | 168K (1)| 00:33:45 | | |
| 3 | HASH GROUP BY | | 12 | 504 | 168K (1)| 00:33:45 | | |
|* 4 | FILTER | | | | | | | |
| 5 | PARTITION RANGE ITERATOR| | 12 | 504 | 168K (1)| 00:33:45 | KEY | KEY |
|* 6 | TABLE ACCESS FULL | M_XXXXX_LOG | 12 | 504 | 168K (1)| 00:33:45 | KEY | KEY |
------------------------------------------------------------------------------------------------------------
一個數據量過億的大表進行大量的全表掃描,確實是很不應該的,不知道是sql的問題還是本身表做了某些變更導致的。 簡單分析了下sql語句,沒有發現問題,帶著疑問查看了表的情況,這個表在這兩天做了重新分割槽的工作。是不是會有一定的影響,查看了分割槽的索引資訊。 結果發現有一個分割槽的索引狀態是UNUSABLE,而這個分割槽就是從top中解析出來sql裡面正在執行的。 所以很可能是這個分割槽導致的問題,不過似乎就這一個索引也不至於這麼嚴重吧,我有查看了另外幾個相關的表,發現另外有幾個大表近期做了分割槽操作。資料分割槽所對應的分割槽索引有幾個都是UNUSABLE,說明分割槽索引不可用。 又查看了其它幾個top程序的情況,發現相關的sql也都在做全表掃描。 如果客戶端連過來幾百個session,都在嘗試做全表掃描,影響可想而知。 修復起來就快得多了,儘管是億級大表,但是rebuild得只是幾個特定的分割槽,所以速度還是比較快的, 使用alter index xxxxx rebuild partition xxxxx的方式進行了修復,為了保險,沒有使用Online的選項。 分割槽索引重建後,再次檢視執行計劃,就步入正軌了,索引都正常啟用了。 問題解決之後,再來回顧這個問題,似乎還是有些不太容易理解,為什麼昨晚的時候資料庫例項就會自動掛掉呢,到底負載有多高呢, 我們可以參考db time這個指標。
DB_NAME BEGIN_SNAP END_SNAP SNAPDATE LVL DURATION_MINS DBTIME
------------------ ---------- ---------- ------------------------------ ---------- ------------- ----------
6214 6215 21 Jul 2015 17:00 1 60 429
6215 6216 21 Jul 2015 18:00 1 60 460
6216 6217 21 Jul 2015 19:00 1 60 221
6217 6218 21 Jul 2015 20:00 1 60 200
6218 6219 21 Jul 2015 21:00 1 60 190
6219 6220 21 Jul 2015 22:00 1 60 1502
可以看到資料庫例項在昨晚掛掉的時候,系統負載出奇的高,遠遠超過了閥值。通過awr檢視,session數也比平時多了一倍。這種負載下,大量的全表掃描進行,勢必對sga是一個很大的衝擊,難怪在開始的時候爆出了w000沒有響應,在MOS 1600807.1,1345364.1都有一些相關的說明。