一次共享内存段异常以及处理
Oracle Trouble Shooting12月 8th, 2009说起来汗颜，我这个BLOG主要写Oracle相关的文章，也附带写点UNIX，可惜从来没正经写过UNIX方面的东西。毕竟不是专业的SA，水平不够恐怕误导读者朋友。这次的故障，主要是从OS层进行处理的，稍微算是沾上一点UNIX的边。闲话少扯了，说正事吧。
事情的起因，是系统的最终用户反映某些查询功能比较慢。简单地看了一下主机的负载以及数据库的性能状况，没发现什么异常，甚至可以说系统相当地轻闲。
那问题出在哪？我首先观察到内存的使用率相当地高，达到99%。但是从操作上看，速度还没受到影响。不过很快想到，这个系统某些模块，用了短连接，难道是监听太慢引起的？这个库启了6个监听（详见《一切皆有可能》），分别TNSPING这几个监听，有个别监听非常慢，重启监听后，查询功能比较慢的问题得到解决。
不过之前观察到的内存的异常使用引起了我极大的注意。这套系统，平时一般都会有几十G的空闲内存，不会达到这么高的。第一反应是用ipcs命令检查一下共享内存，发现有一个异常的共享内存段，占了60多G。
[oracle@hostname%/oracle]ipcs -ma IPC status from /dev/kmem as of Mon Dec 7 10:58:53 2009 T ID KEY MODE OWNER GROUP CREATOR CGROUP NATTCH SEGSZ CPID LPID ATIME DTIME CTIME Shared Memory: m 0 0x41180809 --rw-rw-rw- root root root root 0 348 2725 2725 2:38:57 2:38:57 2:38:50 m 1 0x4e0c0002 --rw-rw-rw- root root root root 2 61760 2725 2727 12:27:19 18:19:39 2:38:50 m 2 0x411c0de1 --rw-rw-rw- root root root root 2 8192 2725 2727 12:27:19 2:38:50 2:38:50 m 3 0x00a5c581 --rw------- sfmdb users sfmdb users 11 10469376 3362 3398 2:39:38 2:39:39 2:39:38 m 4 0x4118043d --rw------- root root root root 1 4096 3410 4745 2:40:12 no-entry 2:40:12 m 5 0x06347849 --rw-rw-rw- root root root root 1 65544 3535 6722 17:53:03 17:53:03 2:39:47 m 1015814 0x0c6629c9 --rw-r----- root dba root dba 0 35921048 6722 6722 17:53:03 no-entry 17:53:03 m 819207 0x491002d0 --rw-r--r-- root root root root 0 22908 3674 3674 2:39:54 2:39:54 2:39:54 m 5472264 0x00000000 D-rw-r----- oracle dba oracle dba 6 66640334848 5508 23604 17:58:00 17:58:00 17:58:00 m 95387657 0x0000cace --rw-rw-rw- root sys root sys 0 2 21306 21306 20:24:33 20:24:33 20:24:29 m 35520522 0xa57bccf8 --rw-r----- oracle dba oracle dba 12231 66640334848 3231 26942 10:58:53 10:58:53 18:10:36
ID为”5472264″的共享内存段就是异常的共享内存段。
为什么会出现这种情况？数据库可以确定是被重启过，询问客户这套系统的DBA，的确是在头一天出现了异常然后进行了重启。至于出现了什么样的异常，为什么要重启，这里不再深入。本文只讨论怎么样来清除这个异常的共享内存段。
由于这个内存段的NTATTCH(number of attach)为6，在HP-UX下是清理不掉的：
[oracle@hostname%/oracle]ipcrm -m 5472264 ipcrm: shmid(5472264): not found
这是由于还有进程attach（理解为连接吧）到这个共享内存段上。只要找到这个进程被KILL之，就会解决问题。一种简单的方法是使用lsof来找到这些进程：
[oracle@hostname%/oracle]lsof | egrep "COMMAND|5472264"
不过简单的方法，不一定效率就高。这个系统光oracle server process就有5000个以上，lsof实在很慢。所以运行几分钟就直接放弃（因为以前在这套系统上运行过lsof命令，知道要输出完结果时间比较“漫长”）。
OK， 手工找一下吧。从上面的ipcs输出的CTIME字段看到，正常的共享内存段是18:10左右创建的，而异常的是17:58左右创建的，那么attach到这个异常共享内存段的进程应该是在18点之前创建，而在17:58左右。首先使用”ps -ef | grep defunct“，没有发现僵死进程。然后根据这样的条件，并且经过一系列筛选，得到下面的结果：
[oracle@hostname%/oracle]ps -ef | grep oraclesidname | grep "17:" | grep -v "18:17" | grep -v "11:17" oracle 22586 1 1 07:17:43 ? 0:31 oraclesidname (LOCAL=NO) oracle 28403 1 0 09:17:38 ? 0:02 oraclesidname (LOCAL=NO) oracle 22618 1 0 07:17:59 ? 0:00 oraclesidname (LOCAL=NO) oracle 7539 1 0 08:17:42 ? 0:10 oraclesidname (LOCAL=NO) oracle 7419 1 0 08:17:05 ? 0:00 oraclesidname (LOCAL=NO) oracle 22580 1 0 07:17:42 ? 0:36 oraclesidname (LOCAL=NO) oracle 7421 1 0 08:17:06 ? 0:06 oraclesidname (LOCAL=NO) oracle 7537 1 0 08:17:42 ? 0:02 oraclesidname (LOCAL=NO) oracle 7535 1 0 08:17:41 ? 0:00 oraclesidname (LOCAL=NO) oracle 21395 1 0 17:56:49 ? 0:01 oraclesidname (LOCAL=NO) oracle 22616 1 0 07:17:59 ? 0:00 oraclesidname (LOCAL=NO) oracle 20786 1 0 17:54:24 ? 0:10 oraclesidname (LOCAL=NO) oracle 22614 1 0 07:17:58 ? 0:00 oraclesidname (LOCAL=NO) oracle 7423 1 0 08:17:06 ? 0:18 oraclesidname (LOCAL=NO)
看上去进程号为21395和20786的进程，正好满足前面提到的条件。KILL这两个进程，检查共享内存段，发现这个异常的共享内存段自动被清除。再检查内存的使用，内存的使用率也大幅下降，回到正常状态。
今天也算是幸运的，在没有监控系统的情况下，人为的较早发现了这个问题，避免了全系统范围内的系统问题。如果没有及时发现这个问题，内存的使用一上去，开始大量使用交换页，那就头疼多了。
12月 8th, 2009 at 3:42 下午
不知道这个这个lsof中的COMMAND|5472264是什么意思
lsof | egrep “COMMAND|5472264″
我在自己的机器上测试了一下，感觉好像不能看出LOSF能找出那些进程正在访问某些内存组织
LINUX AS 4
COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME
init 1 root cwd DIR 104,3 4096 2 /
init 1 root rtd DIR 104,3 4096 2 /
init 1 root txt REG 104,3 32684 20414523 /sbin/init
init 1 root mem REG 104,3 106397 15321198 /lib/ld-2.3.4.so
init 1 root mem REG 104,3 1454462 15321877 /lib/tls/libc-2.3.4.so
init 1 root mem REG 104,3 53736 15319164 /lib/libsepol.so.1
init 1 root mem REG 104,3 56320 15321892 /lib/libselinux.so.1
init 1 root 10u FIFO 0,13 942 /dev/initctl
migration 2 root cwd DIR 104,3 4096 2 /
migration 2 root rtd DIR 104,3 4096 2 /
migration 2 root txt unknown /proc/2/exe
ksoftirqd 3 root cwd DIR 104,3 4096 2 /
ksoftirqd 3 root rtd DIR 104,3 4096 2 /
老熊 Reply:
12月 8th, 2009 at 7:58 下午
@zabll,
就是用egrep 来过滤数据，找到有COMMAND或5472264，前者就是标题头了，后者就是共享内存段的ID
至于linux下的lsof为啥找不到， 得有空去看一下。
12月 8th, 2009 at 5:47 下午
我一直不太明白你们DBA处理事情的方法。
就像这个问题，确认除了出问题的进程是21395和20786，为什么就直接kill？这两个进程是做什么的？kill之后会有什么影响？
老熊 Reply:
12月 8th, 2009 at 8:00 下午
@Nobody,
这两个进程是oracle的进程，并且启动时间上看是异常的（就是不应该存在这里）。至于KILL会有什么影响，对这个案例来说，没有丝毫不利的影响。
12月 8th, 2009 at 10:10 下午
HP有个工具可以看使用内存段的都是哪些进程，具体名字忘记了，回头查查。
12月 8th, 2009 at 10:18 下午
D-rw-r----- 前面有D，意思好像说这个共享内存段有问题，HP的那个工具叫shminfo。
老熊 Reply:
12月 9th, 2009 at 10:03 上午
@jlttt,
感谢提供的方法。
不过我看了一下，系统上没有这个工具，不过我自己的电脑上以前倒是下载了一个，放了很久，都忘记了。是一个工具包的一个组件：toolset.64bit.exe
不过运行这个需要root权限。
12月 11th, 2009 at 11:12 下午
前面有D，说明该共享内存段已经被删除。NATTCH=6，说明有6个进程正在访问这个共享内存段，所以内存段一直没有释放。
shminfo是HP的小工具，打HP热线，HP就给传一个。
老熊 Reply:
12月 11th, 2009 at 11:48 下午
@jlttt, 不过当时有个HP工程师没搞定，打了电话也没有搞定。
12月 12th, 2009 at 12:25 下午
ATIME 和DTIME是什么意思？昨天查了一下没有查到
老熊 Reply:
12月 12th, 2009 at 9:45 下午
@SAPER,
atime,dtime,ctime 应该第一个字母是指 last access、last detach, create。
1月 5th, 2010 at 1:22 下午
dtime含义：
DTIME
The time the last shmdt() detach was completed on the associated shared memory segment.
http://www.docs.hp.com/en/B2355-60105/ipcs.1.html
老熊 Reply:
1月 5th, 2010 at 2:52 下午
@szp, 谢谢