说起来汗颜,我这个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这两个进程,检查共享内存段,发现这个异常的共享内存段自动被清除。再检查内存的使用,内存的使用率也大幅下降,回到正常状态。

今天也算是幸运的,在没有监控系统的情况下,人为的较早发现了这个问题,避免了全系统范围内的系统问题。如果没有及时发现这个问题,内存的使用一上去,开始大量使用交换页,那就头疼多了。

Trackback

13 comments untill now

  1. 不知道这个这个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:

    @zabll,
    就是用egrep 来过滤数据,找到有COMMAND或5472264,前者就是标题头了,后者就是共享内存段的ID

    至于linux下的lsof为啥找不到, 得有空去看一下。

  2. 我一直不太明白你们DBA处理事情的方法。
    就像这个问题,确认除了出问题的进程是21395和20786,为什么就直接kill?这两个进程是做什么的?kill之后会有什么影响?

    老熊 Reply:

    @Nobody,
    这两个进程是oracle的进程,并且启动时间上看是异常的(就是不应该存在这里)。至于KILL会有什么影响,对这个案例来说,没有丝毫不利的影响。

  3. HP有个工具可以看使用内存段的都是哪些进程,具体名字忘记了,回头查查。

  4. D-rw-r—– 前面有D,意思好像说这个共享内存段有问题,HP的那个工具叫shminfo。

    老熊 Reply:

    @jlttt,
    感谢提供的方法。
    不过我看了一下,系统上没有这个工具,不过我自己的电脑上以前倒是下载了一个,放了很久,都忘记了。是一个工具包的一个组件:toolset.64bit.exe

    不过运行这个需要root权限。

  5. 前面有D,说明该共享内存段已经被删除。NATTCH=6,说明有6个进程正在访问这个共享内存段,所以内存段一直没有释放。
    shminfo是HP的小工具,打HP热线,HP就给传一个。

    老熊 Reply:

    @jlttt, 不过当时有个HP工程师没搞定,打了电话也没有搞定。

  6. ATIME 和DTIME是什么意思?昨天查了一下没有查到

    老熊 Reply:

    @SAPER,
    atime,dtime,ctime 应该第一个字母是指 last access、last detach, create。

  7. 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:

    @szp, 谢谢

Add your comment now