数据库服务器宕机原因分析

dywjzh

服务器环境：RHEL 5.8_64
ORACLE环境：单机11.2.0.2.0

11号那天一数据库服务器宕机，应用无法使用，远程ssh不行，但是可以ping通。到现场后使用显示器键盘鼠标连接后没反应（确认这些设备是完好的），但是各类指示灯都是绿色闪烁，只能强制重启，重启过程中没看见报错信息，重启后oracle正常启动，业务也正常运行。

由于是重启过的机器，无法查询当时宕机是的信息，只能通过日志分析原因。

我的分析过程如下：

在下午1点45左右，有客户反映无法连接服务器，然后使用putty远程登录服务器卡住，但是可以ping通，说明网络没有问题，问题出现在服务器上面。

等待10分钟左右，仍然未见好转，判断服务器应该是卡住了，需要去现场处理。

2点左右出门，打车到岗顶机房，用时30分钟左右到达机房。

到达机房后，检查服务器外表，无任何异常情况，电源灯正常绿色，硬盘灯正常绿色闪烁，网卡正常绿色闪烁，决定连接显示器键盘鼠标查看详细情况。

在使用外接键盘鼠标和显示器连接服务器时，发现无响应，说明此时服务器无法响应设备，或者说没有资源去响应。只能强制重启服务器。

强行重启服务器时，可以看到在启动过程，说明服务器刚刚是没法响应外接设备，也就是说刚刚服务器确实是没有资源了。

服务器启动过程的显示没有任何异常，启动后查看硬盘、内存、CPU、网络等，都正常运行。oracle和weblogic已经自动启动。客户可以正常连接了。

业务正常运行后，检查日志文件。

首先查看系统日志，/var/log/message系列日志。查看到日志文件中最接近发生错误的时间的日志如下：
Mar 10 04:02:03 server01 syslogd 1.4.1: restart.
Mar 12 14:17:50 server01 kernel: INFO: task kjournald:1008 blocked for more than 120 seconds.
Mar 12 14:17:50 server01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 12 14:17:50 server01 kernel: kjournald     D ffffffff80156347     0  1008    185          1034   955 (L-TLB)
Mar 12 14:17:50 server01 kernel:  ffff81042dd41dd0 0000000000000046 ffff810428c9d850 ffff81006a8b9bb0
Mar 12 14:17:50 server01 kernel:  0000000000000000 000000000000000a ffff81042dc31820 ffff81013bf4b820
Mar 12 14:17:50 server01 kernel:  003b3104ba0221b6 0000000000000c64 ffff81042dc31a08 000000058008e66b
Mar 12 14:17:50 server01 kernel: Call Trace:
Mar 12 14:17:55 server01 kernel:  [<ffffffff88033661>] :jbd:journal_commit_transaction+0x173/0x10c2
Mar 12 14:17:59 server01 kernel:  [<ffffffff800a3444>] autoremove_wake_function+0x0/0x2e
Mar 12 14:17:59 server01 kernel:  [<ffffffff8004ad6b>] try_to_del_timer_sync+0x7f/0x88
Mar 12 14:17:59 server01 kernel:  [<ffffffff880376a3>] :jbd:kjournald+0xc1/0x213
Mar 12 14:17:59 server01 kernel:  [<ffffffff800a3444>] autoremove_wake_function+0x0/0x2e
Mar 12 14:17:59 server01 kernel:  [<ffffffff880375e2>] :jbd:kjournald+0x0/0x213
Mar 12 14:17:59 server01 kernel:  [<ffffffff800a322c>] keventd_create_kthread+0x0/0xc4
Mar 12 14:17:59 server01 kernel:  [<ffffffff80032679>] kthread+0xfe/0x132
Mar 12 14:17:59 server01 kernel:  [<ffffffff8005dfb1>] child_rip+0xa/0x11
Mar 12 14:17:59 server01 kernel:  [<ffffffff800a322c>] keventd_create_kthread+0x0/0xc4
Mar 12 14:17:59 server01 kernel:  [<ffffffff8003257b>] kthread+0x0/0x132
Mar 12 14:17:59 server01 kernel:  [<ffffffff8005dfa7>] child_rip+0x0/0x11
1点40左右出现的问题，但是此日志文件2点17分才出现日志，可以判断出，这段日志没有记录出错时的情况。

然后查看oracle警告日志，/u01/app/oracle/diag/rdbms/r5/r5/trace/alert_r5.log，进去后发现最接近错误时间的日志如下：
Tue Mar 12 12:58:45 2013
Archived Log entry 19964 added for thread 1 sequence 20426 ID 0x88aedba3 dest 1:
Tue Mar 12 13:39:41 2013
Process J000 died, see its trace file
kkjcre1p: unable to spawn jobq slave process
Errors in file /u01/app/oracle/diag/rdbms/r5/r5/trace/r5_cjq0_7348.trc:
Process J000 died, see its trace file
kkjcre1p: unable to spawn jobq slave process
Errors in file /u01/app/oracle/diag/rdbms/r5/r5/trace/r5_cjq0_7348.trc:
Tue Mar 12 13:39:55 2013
...

红色前面的日志是正常的归档日志，红色部分开始就是错误日志了，这个时间非常接近客户反映连接不上时的时间，下面是一堆类似的日志，使用省略号代替。
根据提示，查看/u01/app/oracle/diag/rdbms/r5/r5/trace/r5_cjq0_7348.trc文件，找到对应时间的日志，如下：
*** 2013-03-12 02:00:00.062
Closing Resource Manager plan via scheduler window
Clearing Resource Manager plan via parameter

*** 2013-03-12 13:39:37.783

*** 2013-03-12 13:39:40.228
Process J000 is dead (pid=25974 req_ver=3997 cur_ver=3997 state=KSOSP_SPAWNED).

*** 2013-03-12 13:39:46.384
Process J000 is dead (pid=25995 req_ver=8055 cur_ver=8055 state=KSOSP_SPAWNED).

*** 2013-03-12 13:39:55.053
Process J000 is dead (pid=26000 req_ver=8056 cur_ver=8056 state=KSOSP_SPAWNED).
...

*** 2013-03-12 14:17:55.965
Memory (Avail / Total) = 75.88M / 16008.41M
Swap (Avail / Total) = 0.00M /  5999.63M
skgpgcmdout: read() for cmd /bin/ps -elf | /bin/egrep 'PID | 26239' | /bin/grep -v grep timed out after 14.630 seconds
Skipping stack dump because max dump time exceeded.
...

黑色部分和前面的都是正常的日志，红色部分开始，就是服务器宕机时间的日志了。网上查询资料，基本上都说原因是会话数满了，但是我不认同这个结论。因为基本上服务器的会话数是140个左右，而我设置的最大会话数是300个，因此不应该是会话数的原因。而且一般来说会话数满了那也应该是登录不了数据库，而此服务器的情况是无法ssh登录，而且连接显示器和键盘鼠标都没反应。但是又能ping通。而在2点18分的时候出现了提示内存可以只有几十M，swap为0的日志。

接着查看weblogic的日志，发现错误情况如下：
<2013-3-12 下午01时40分52秒 CST> <Warning> <JDBC> <BEA-001129> <Received exception while creating connection for pool "SDSH": ORA-01034: ORACLE not available
ORA-27102: out of memory
Linux-x86_64 Error: 12: Cannot allocate memory
Additional information: 1
Additional information: 4587528
Additional information: 8
也是在oracle出现问题之后才导致的内存不足。

根据oracle日志提示的：Process J000 is dead，说明当时应该是process满了，导致资源不足而卡住，但是我之前遇到过的process满了不会出现宕机这么严重的事情，仅仅是oracle连接不上而已。之前由于之前出现过process不足的情况，我已经把process最大设置到300了，平时也就用到140左右。所以我猜测不应该是process满了的原因，请大家帮忙分析一下，谢谢了。

下面给出日志文件：

Maclean Liu(刘相兵

[oracle@vrh8 ~]$ egrep -i "memory|swap" r5_cjq0_7348.trc.txt
Memory (Avail / Total) = 75.88M / 16008.41M
Swap (Avail / Total) = 0.00M /  5999.63M
Memory (Avail / Total) = 75.98M / 16008.41M
Swap (Avail / Total) = 0.00M /  5999.63M

如果上述信息可信的话 ，那么 看起来是swap耗尽了。


Mar 12 14:17:50 server01 kernel: INFO: task kjournald:1008 blocked for more than 120 seconds.


建议你观察下 系统的内存使用情况， 最好能部署oswatcher 监控工具 那么下次就可以明确了解问题所在了。

sunnyihui

我遇到好多次这种问题，客户上新的业务，tuxedo一直吃内存，发生内存泄露，导致小机没有内存了，ssh不了，显示器也不显示，只能按钮关机。启动

Stone

11号那天一数据库服务器宕机 ....

根据日志应该是12号，要么就是server的时间快一天 :)

根据oracle日志提示的：Process J000 is dead，说明当时应该是process满了，导致资源不足而卡住，但是我之前遇到过的process满了不会出现宕机这么严重的事情，仅仅是oracle连接不上而已。之前由于之前出现过process不足的情况，我已经把process最大设置到300了，平时也就用到140左右。所以我猜测不应该是process满了的原因

很可能是因为进程“异常”，造成进程无法释放，一直累积，进而大量的资源被消耗殆尽，所以所有对服务器的请求都没有了响应，包括应用的请求，以及你自己尝试登陆连接。 而这是完全可能的事情 ~， 与平时“正常”时的表现无关，当然按正常连接的话，也不可能消耗完资源。问题很有可能是操作系统层面的异常进程过多，造成资源用完，最终导致数据库的资源请求得不到满足。 可以考虑下有没有异常的crontab job, 当时的CPU负载，以及存储可能的问题，当然没有日志也就不好说啦。ML建议的是一个很好的记录平时日志的方法，以方便追踪元凶。 当然也可以咨询下系统工程师，看看有莫有什么线索啦。

Good luck

dywjzh

Maclean Liu(刘相兵 发表于 2013-3-14 21:44
[oracle@vrh8 ~]$ egrep -i "memory|swap" r5_cjq0_7348.trc.txt
Memory (Avail / Total) = 75.88M / 1600 ...

谢谢回复，我已经在准备监控软件了。
不过oswatcher 监控工具 没用过，有空我去了解一下。

dywjzh

sunnyihui 发表于 2013-3-14 21:50
我遇到好多次这种问题，客户上新的业务，tuxedo一直吃内存，发生内存泄露，导致小机没有内存了，ssh不了， ...

感谢提供的信息

dywjzh

Stone 发表于 2013-3-14 22:08
根据日志应该是12号，要么就是server的时间快一天 :)

时间那里我搞错了，应该是12号，crontab job是没有的，我的job都是晚上做的，已经准备监控软件了了。
谢谢回复