今天来到办公室，发现有一台服务器中的数据库实例停掉了。这种情况真是意料之外，尤其是我还不是很熟悉这台机器的服务。
赶紧查看数据库日志，可以看到数据库在昨晚停掉了，从日志来看没有人为的痕迹。
在宕机之前，有下面的日志。在此截取一部分。
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
1600807.1,1345364.1
都有一些相关的说明。本文章为转载内容，我们尊重原作者对文章享有的著作权。如有内容错误或侵权问题，欢迎原作者联系我们进行内容更正或删除文章。
