一次数据库宕机问题的分析

今天来到办公室，发现有一台服务器中的数据库实例停掉了。这种情况真是意料之外，尤其是我还不是很熟悉这台机器的服务。
赶紧查看数据库日志，可以看到数据库在昨晚停掉了，从日志来看没有人为的痕迹。
在宕机之前，有下面的日志。在此截取一部分。
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