内存异常消耗诊断案例

转自：http://blog.csdn.net/lunar2000/article/details/404111

本文已经发表在ITPUB优化技术丛书，未经许可，不得转载。

（作者不让转，但是小弟就是为了有个记录，没有商业用途哈，非要追究我的话，我就删了。。嘿嘿）

1.   问题发现

一大早，接到通知说现网数据库（RAC中的一个节点）出现异常，现象是大量的业务拥堵，系统可用内存很低，经常徘徊在100m左右，随着业务高峰期的时间就要到了，眼看系统的内存已经处在极其危险的状态。

 

2.   解决过程

2.1. 环境介绍

硬件和软件环境：

HP 7410  ，16G内存，8个CPU，存储是HP XP128

OS版本，HPUX 11.11 + MC 11.15

2节点RAC，oracle版本9.2.0.4

2.2. 问题现象

首先看一下进程的内存情况（HPUX 11.11）：

oracle@db02:/oracle > vmstat 2 10          procs           memory                   page                              faults       cpu     r     b      w       avm      free       re       at    pi   po    fr   de    sr     in     sy    cs  us sy id     8     5    0  2659897   54987  127   13     0    0     0    0    23  17401 114389  6145  21  6 73     8    5     0  2659897   54365    4     0       4     0     0    0     0  16032 126259  7605  35  5 60     8     5     0  2659897   54232    2     0      3     0     0    0     0  16043 139904  7705  38 11 51     2    5     0  2664805   53921    0     0     32     0     0    0     0  16252 141213  7843  33  6 60     2    5     0  2664805   56209    0     0      20    0     0    0     0  15828 136485  7592  30  6 65     2     5     0  2664805   55701    0     0     56    0     0    0     0  16330 137069  7952  38  7 54     2     5     0  2664805   55685    0     0     35    0     0    0     0  16819 141478  8098  32  6 62     2     5     0  2664805   53749    0     0     22    0     0    0     0  16855 139303  8003  34  7 59     7     1     0  2620255   51536  172    0    41    0     0    0     0  16521 136507  8093  44  6 50     7     1     0  2620255   51323  109    0    28    0     0    0     0  17859 151458  8623  43  7 50 oracle@db02:/oracle >

我们知道，一般来说，系统的Page out(po)可以有一些，但如果Page in(pi)一般很高，并间歇性的还在逐渐上升，这就要引起注意。总得来说，正常系统的paging 可以有一些，但不能太多。而这里，很明显，我们可以看见运行队列（r）很高，系统可用的空闲内存极少，并切伴随大量的page in，已经出现了明显的内存不足。同时我们也可以看到用户进程的CPU使用率（us）几乎没有异常，并且他们的cpu的使用率都在合理的范围内（抛除wait－io意味的CPU使用率）。

再使用top观察，是否有大量的极其耗费CPU的进程在操作：

oracle@db02:/oracle > top        System: db02                                       Fri Mar  4 12:14:47 2005 Load averages: 0.56, 0.57, 0.58 966 processes: 951 sleeping, 15 running Cpu states: CPU   LOAD   USER   NICE    SYS   IDLE  BLOCK  SWAIT   INTR   SSYS  0      0.65  30.0%   0.0%   5.7%  64.3%   0.0%   0.0%   0.0%   0.0%  1      0.77  95.7%   0.0%   1.0%   3.4%   0.0%   0.0%   0.0%   0.0%  2      0.64  24.9%   0.0%  11.6%  63.5%   0.0%   0.0%   0.0%   0.0%  3      0.40  36.5%   0.0%   7.3%  56.2%   0.0%   0.0%   0.0%   0.0%  4      0.59  27.2%   0.0%   7.7%  65.1%   0.0%   0.0%   0.0%   0.0%  5      0.54  26.4%   0.0%   7.3%  66.3%   0.0%   0.0%   0.0%   0.0%  6      0.60  17.8%   0.0%  11.4%  70.8%   0.0%   0.0%   0.0%   0.0%  7      0.29  36.3%   0.0%   3.6%  60.2%   0.0%   0.0%   0.0%   0.0% ---   ----  -----  -----  -----  -----  -----  -----  -----  ----- avg   0.56  36.9%   0.0%   6.9%  56.2%   0.0%   0.0%   0.0%   0.0%   Memory: 14829952K (8998976K) real, 20328344K (10419100K) virtual, 227036K free  Page# 1/35   CPU TTY  PID USERNAME PRI NI   SIZE    RES STATE    TIME %WCPU  %CPU COMMAND  7   ?  8946 oracle   241 20  7328M  2148K run     13:56 99.14 98.97 ora_j002_cmc2  4   ? 11551 oracle   241 20  7344M 14384K run    148:31 22.84 22.80 oraclecmc2    0   ? 22315 oracle   221 20  7358M  5668K run    294:01 18.22 18.19 ora_lms0_cmc2  3   ? 22317 oracle   154 20  7358M  5668K sleep  307:13 17.89 17.86 ora_lms1_cmc2    1   ?  9108 oracle   241 20  7328M  2820K run      0:06 17.31 17.28 oraclecmc2    0   ?  9106 oracle   154 20  7328M  2928K sleep    0:22 10.87 10.85 oraclecmc2  1   ?  7044 oracle   154 20  7333M  5720K sleep    0:45  7.25  7.24 oraclecmc2  2   ? 11591 oracle   154 20  7328M   864K sleep  183:59  7.25  7.24 oraclecmc2  4   ?  7235 root     152 20 43172K  7236K run      4:03  7.04  7.02 nco_m_ssmagent  6   ? 11687 oracle   156 20  7328M   852K sleep   86:09  6.27  6.26 oraclecmc2  4   ?  3650 oracle   154 20  7328M   816K sleep    7:11  5.54  5.53 oraclecmc2    0   ? 11384 oracle   154 20  7328M   844K sleep   79:19  5.47  5.46 oraclecmc2  5   ?  8772 oracle   154 20  7328M  2420K sleep    1:00  5.02  5.01 oraclecmc2    3   ? 10083 oracle   154 20  7328M  1052K sleep   71:55  5.00  4.99 oraclecmc2    3   ? 22335 oracle   156 20  7335M  2604K sleep   67:37  4.94  4.94 ora_lgwr_cmc2  2   ?  8836 root     -16 10 39044K 18820K run      0:36  3.02  3.01 midaemon  4   ?  3225 oracle   154 20  7328M   844K sleep    3:55  2.95  2.95 oraclecmc2    6   ? 22339 oracle   148 20  7328M  1560K sleep   47:11  2.60  2.60 ora_smon_cmc2  6   ?     0 root     127 20    32K     0K sleep   48:24  2.34  2.34 swapper  2   ?  5115 oracle   154 20  7332M  2072K sleep    4:06  1.73  1.72 oraclecmc2    2   ?  7607 oracle   154 20  7353M  1548K sleep    1:39  1.67  1.67 oraclecmc2    4   ? 22313 oracle   154 20  7334M  3992K sleep   22:38  1.65  1.65 ora_lmd0_cmc2    3   ?  4824 oracle   154 20  7332M  3160K sleep    3:12  1.53  1.53 oraclecmc2    3   ?  4896 oracle   154 20  7332M  3168K sleep    4:05  1.50  1.50 oraclecmc2  1   ?  9697 oracle   154 20  7332M  3460K sleep    4:06  1.50  1.50 oraclecmc2  5   ?  9733 oracle   154 20  7332M  2672K sleep    4:25  1.39  1.39 oraclecmc2  4   ? 11487 oracle   154 20  7328M  1064K sleep    9:46  1.34  1.34 oraclecmc2 oracle@db02:/oracle >

2.3. 对比分析

这里可以清楚的看到空闲内存只有200M，并且几乎每个进程伴随都有很高的wait－io。于是想到对比以前的系统性能记录：

oracle@db02:/oracle > sar -u 2 10   HP-UX db02 B.11.11 U 9000/800    02/08/05   18:32:24    %usr    %sys    %wio   %idle 18:32:26      34       5      19      43 18:32:28      39       7      18      37 18:32:30      37       6      15      42 18:32:32      31       5      12      51 18:32:34      29       4       9      57 18:32:36      28       4      10      57 18:32:38      31       4      14      52 18:32:40      35       5      12      48 18:32:42      39       3      10      49 18:32:44      42       5      16      37   Average       35       5      14      47 oracle@db02:/oracle >

使用sar –u 命令我们看到，那时的系统状态是非常良好的，CPU的idel平均值（%idle）在47％，而系统的wait io（%wio）的平均值在14％，这是一个比较理想的状态。

再来看系统正常时候的内存使用情况：

oracle@db02:/oracle > vmstat 2 10          procs           memory                   page                              faults       cpu     r     b     w      avm          free           re   at    pi   po    fr   de    sr     in     sy    cs  us sy id     5     2     0   930013  1008560  127    9     0    0     0    0     0  17382 114792  6110  21  6 73     6     2     0   988914  1007728  208   40     0    0     0    0     0  15703 128093  7582  47  7 46     6     2     0   988914  1007665  203   50     0    0     0    0     0  15603 127244  7496  42  6 52     6     2     0   988914  1007664  213   63     0    0     0    0     0  15444 126853  7647  48  6 45     6     2     0   988914  1007552  136   40     0    0     0    0     0  15592 133625  7417  39  4 56     6     2     0   988914  1007265  163   54     0    0     0    0     0  15733 140186  7161  40  5 54     4     1     0  1004118  1007248  104   34     0    0     0    0     0  15356 137336  6836  44  5 51     4     1     0  1004118  1006640  130   46     1    0     0    0     0  15461 138396  6926  38  5 57     4     1     0  1004118  1006641  163   59     1    0     0    0     0  16366 148071  7617  42  6 51     4     1     0  1004118  1006640  104   37     1    0     0    0     0  15761 136805  7334  40  4 55 oracle@db02:/oracle >

我们看到，虽然也存在有一些等待队列，但是系统的可用内存在4G左右（free*page size=1008560*4096=4131061760 byte）。系统的几乎没有page in。

情急之下，请业务人员停掉一个应用，以便系统稳定在free memory在200M左右，然后开始进一步定位问题的原因。

现在，检查一下当前的oracle进程数目，是否由于今天的业务太多，或者连接的用户太多造成的压力呢？

oracle@db02:/oracle > ps -ef | grep oracle| wc -l 842 oracle@db02:/oracle >

这个数值和平时相比，是一个非常正常的值，系统曾经在并发连接数目达到1200以上仍然正常工作，因此排除了业务过量导致系统资源不足的可能性。

现在需要尽快找到入手的线索，既然内存不足，存在大量的page in操作，那么看一下交换分区的使用状态：

oracle@db02:/oracle > swapinfo              Kb      Kb      Kb   PCT  START/      Kb TYPE      AVAIL    USED    FREE  USED   LIMIT RESERVE  PRI  NAME dev     32768000 4058864 28709136   12%       0       -    1  /dev/vg00/lvol2 reserve       - 15057520 -15057520 memory  12954600 1303496 11651104   10% oracle@db02:/oracle >

我们看见，一个正常的系统，交换分区的使用应该在5％以内，这里交换区使用率已经达到了12％，远远超过这个一般HP系统的常规值。

2.4. 假设和分析

联系所有上面的现象，我们已经基本可以断定，系统今天的现象绝对不是由于某些单纯的用户进程引起的，应该有几种可能：

1，Oracle 的SGA设置不合理

2，Oracle 的 PGA使用有异常

3，有可能某些僵死的进程不能正常释放内存

4，有某些认为的操作造成了内存泄漏

5，遇到了HP 或者Oracle某些bug

我们逐步检查上述原因，继续寻找线索。首先，考虑到既然操作系统上连接的Oracle用户进程数目正常，会不会oracle的SGA设置不合理呢？

SQL> show sga   Total System Global Area 7391385520 bytes Fixed Size                           747440 bytes Variable Size            3070230528 bytes Database Buffers    4294967296 bytes Redo Buffers                 25440256 bytes SQL>

使用show sga可以清楚的看见，Oracle的SGA区仅仅的占用了物理内存7.3G左右，其中，Data buffer 使用了4G。对于这是一个有着16G物理内存的HP 7410来说，专门的作为Oracle 数据库服务器，并且没有任何的用户应用跑在上面，那么这个设置显然没有什么异常（在正常情况下，我们甚至曾经预计将再将1G到2G的系统空闲内存的分给Oracle的Data buffer来是用的）。

       排除了SGA设置过大的可能性，接下来看看，用户进程的时候是否有什么异常现象？这里我新建立一个连接，在不作任何操作的情况下，看看一个空的连接对系统PGA的使用情况，以观察是否有系统的bug导致的每个Oracle用户进程过渡消耗内存的可能性：

SQL> select distinct sid from v$mystat;             SID ----------        206 Elapsed: 00:00:00.01 SQL>  select b.PGA_USED_MEM PGA_USED_MEM, b.PGA_ALLOC_MEM PGA_ALLOC_MEM,     b.PGA_FREEABLE_MEM PGA_FREEABLE_MEM,b.PGA_MAX_MEM PGA_MAX_MEM     from v$session a, v$process b    where a.PADDR=b.ADDR and a.sid ='&sid' ————用这个查询语句就可以查询出每个会话锁占用的PGA的使用量。 SQL> / Enter value for sid: 206 old   4: where a.PADDR=b.ADDR and a.sid ='&sid' new   4: where a.PADDR=b.ADDR and a.sid ='206'   PGA_USED_MEM          PGA_ALLOC_MEM             PGA_FREEABLE_MEM            PGA_MAX_MEM ------------                              -------------                                ----------------                                    -----------       330201                            612345                                      0                                               11884537 Elapsed: 00:00:00.02

很明显，一个空的进程只需要300k的内存，这是非常正常的状态。现在再观察，系统总的PGA的使用情况，看看有什么发现：

SQL> select sum(PGA_USED_MEM) from v$process; SUM(PGA_USED_MEM) -----------------     561546135 Elapsed: 00:00:00.08 SQL> select sum(PGA_USED_MEM) from v$process; SUM(PGA_USED_MEM) -----------------         409176749 Elapsed: 00:00:00.00 SQL>

    这里，我们观察到，系统总的PGA的使用基本上稳定在400M到700M之间（系统设置的PGA的最大值是1G），与往常相比也是一个非常合理的状态。

2.5. 找到根源

到这里，我们可以作个简单的加减法计算，总的物理内存16G，减去Oracle SGA 占用的7.3G，再减去PGA占用的400M到700M（每时每刻根据使用情况在变话，最大为1G），再减去系统使用的和系统上显示的空闲内存，还应该有至少6个多G的内存去了哪里？

这台主机只用于数据库服务器，因此没有跑任何应用的情况下，因此不存在某些应用服务异常而占用过量共享内存段导致的内存不足（这样的案例是存在的），那么我在这里做过大胆的假设，应该是有某些异常的进程，异常的使用了将近6个多G的共享内存段，如果可以找到哪个共享内存段被谁异常使用，应该就可以找到上述种种问题的答案。

按照这个假设，我们使用ipcs观察共享内存段的使用情况：

oracle@db02:/oracle/app/oracle/admin/cmc/udump > ipcs -mb IPC status from /dev/kmem as of Fri Mar  4 15:57:17 2005 T      ID     KEY        MODE        OWNER     GROUP  SEGSZ Shared Memory: m       0 0x411c5552 --rw-rw-rw-      root      root    348 m       1 0x4e0c0002 --rw-rw-rw-      root      root  61760 m       2 0x412040ba --rw-rw-rw-      root      root   8192 m   15875 0x5e1003c9 --rw-------      root      root    512 m  260612 0x00000000   D-rw-r-----    oracle       dba 6267330560 m 8103429 0x00000000 --rw-r-----    oracle       dba 6442450944 m       6 0x06347849 --rw-rw-rw-      root       dba  77384 m       7 0xffffffff --rw-r--rw-      root       dba  22908 m 6940680 0x320fb498 --rw-r-----    oracle       dba 982507520 oracle@db02:/oracle/app/oracle/admin/cmc/udump >

我们注意到了确实有一个异常的共享内存段（Share Memory ID 为260612），而它也刚好占用了6.2G左右的内存。这是一个Oracle用户占用的共享内存段，由于状态为D的共享内存段本身就是没有正常使用的内存段，所以满以为使用ipcrm –m 260612删除这个共享内存段，应该就可以解决问题，但是，当时上述做法的结果是系统报告找不到找个ID。

 

再看一下共享内存的详细使用信息：

oracle@db02:/oracle/app/oracle/product/920/bin > ipcs -ma IPC status from /dev/kmem as of Fri Mar  4 16:25:19 2005 T      ID     KEY        MODE    CREATOR    CGROUP NATTCH  SEGSZ  CPID  LPID   ATIME    DTIME    CTIME Shared Memory: m       0 0x411c5552 --rw-rw-rw-    root      root      0    348   528   528  4:35:46  4:35:46  4:35:39 m       1 0x4e0c0002 --rw-rw-rw-    root      root      2  61760   528   530  4:36:40  4:35:46  4:35:39 m       2 0x412040ba --rw-rw-rw-    root      root      2   8192   528   530  4:36:40  4:35:39  4:35:39 m   15875 0x5e1003c9 --rw-------    root      root      1    512  1323  1323  4:37:10 no-entry  4:37:10 m  260612 0x00000000 D-rw-r-----  oracle       dba      1 6267330560 15316 17931  2:27:03  2:29:53  2:29:41 m 8103429 0x00000000 --rw-r-----  oracle       dba    738 6442450944 22305 17897 16:24:24 16:25:15  2:53:58 m       6 0x06347849 --rw-rw-rw-    root       dba      0  77384 12170 18503 16:21:41 16:21:41 10:20:38 m       7 0xffffffff --rw-r--rw-    root       dba      0  22908 12169 12169 10:20:40 10:20:40 10:20:40 m 6940680 0x320fb498 --rw-r-----  oracle       dba    738 982507520 22305 17897 16:24:24 16:25:15  2:53:58 m 6833161 0x0c6629c9 --rw-r-----    root       dba      2 17602880 18503 18502 16:21:41 no-entry 16:21:41 oracle@db02:/oracle/app/oracl

这里有一个误解，CPID是指创建这个共享内存段的进程号，常见时间是2：29分，LPID是最后一次获取和使用这个共享内存段的进程号，使用时间是2：29分。因为Oracle在创建了这个段之后这个进程的使命也就完成了，可以简单的理解为类似一个sh脚本执行完成后正常退出的过程，通理，最后一次使用这个共享内存段的LPID的值也是这个道理。所以，如果试图通过这两个进程号来查找进程信息或者kill这两个进程的时候，是不会有什么结果的（kill这两个进程的时候，系统确报告说找不到这个进程）。

这里我们观察到他两个正常的Oracle共享内存段 的创建时间分别都似乎2：53分。联想起几天前由于修改业务而曾经重新启动过数据库。那么这里再做一个假设，这块内存被oracle系统进程异常占用，或者是数据库shutdown时没有正常释放所有的共享内存段。换个角度说，在数据库shutdown时，操作系统没有正常的收回所有的共享内存段。

2.6. 解决问题

       现在我们使用shminfo（需要使用root权限）查看一下当前到底哪个进程在使用这个共享内存段：

db02#[/]./shminfo -s 260612 libp4 (7.0): Opening /stand/vmunix /dev/kmem   Loading symbols from /stand/vmunix shminfo (3.6)   Shmid 260612: struct shmid_ds at 0xf468e8 Pseudo vas at 0x594fd900 Pseudo pregion at 0x624a1d00 Shared region at 0x788a53c0 Segment at 0xd8d3400.0xc000000040000000 Segment allocated out of "Global 64-bit quadrant 4" Processes using this segment: proc=0x6d635040 (pid 17927 "oracle"): vas=0x61faee00, SHMEM preg=0x7dc32180 db02#[/]

现在，很清楚的看到，进程 17927 正在使用该共享内存段。接着，再使用ps查看 17927 的进程信息：

db02#[/]ps -ef|grep 17927     root 18107 18038  1 16:13:25 pts/tn    0:00 grep 17927   oracle 17927     1  0  Feb  6  ?        93:09 ora_diag_cmc2 db02#[/]

请注意，进程名称是 ora_diag_cmc2，这是一个后台诊断进程（Diagnosability Daemon），一般出现在OPS和RAC系统中，多用于在实例crash前生长大量的系统跟踪文件和SYSTEM DUMP信息（生成的所有进程跟踪信息一般存放在bdump目录下一个以故障时间点命名的core目录中）。

通过该进程的时间可以看到，这是2月6号 创建的进程，事实上，我在3月3号晚上重起了数据库，这个进程的创建时间和上面的共享内存段的创建时间和最后使用时间存在出入。由于是现网数据库，在确定删除该进程前我们特意对比了一下RAC中的另一个正常节点：

db02#[/]ps -ef |grep ora_diag_cmc     root 19117 18855  0 16:36:24 pts/to    0:00 grep ora_diag_cmc   oracle 22309     1  0  Mar  3  ?         0:19 ora_diag_cmc2   oracle 17927     1  1  Feb  6  ?        93:09 ora_diag_cmc2 db02#[/]   oracle@cs_db01:/oracle > ps -ef | grep ora_diag_cmc   oracle  3494  3457  0 16:37:11 pts/te    0:00 grep ora_diag_cmc   oracle 14718     1  1  Mar  3  ?         6:20 ora_diag_cmc1 oracle@cs_db01:/oracle >

经过对比，我们发现节点1（正常的节点）只有一个3月3号创建的后台诊断进程，而节点2（异常的节点）存在两个后台诊断进程，一个是3月3号创建的，一个是2月6号创建的。

至此，已经可以确定，进程 17927 就是异常占用6G以上的异常Oracle 后台（系统）进程，可以删除，于是kill它：

db02#[/]kill 17927 db02#[/]ps -ef |grep ora_diag_cmc   oracle 22309     1  0  Mar  3  ?         0:19 ora_diag_cmc2     root 19661 18855  2 16:45:53 pts/to    0:00 grep ora_diag_cmc db02#[/]

现在，再来看看系统性能：

db02#[/]vmstat 2 5          procs           memory                   page                              faults       cpu     r     b     w      avm    free   re   at    pi   po    fr   de    sr     in     sy    cs  us sy id     2     0     0   933372  1544205  127   13     0    0     0    0    31  17401 114427  6148  21  6 73     2     0     0   933372  1544193    8    0     4    0     0    0     0  12975  95961  5599  15  4 81     2     0     0   933372  1543328    4    0     3    0     0    0     0  12989  94187  5522  14  4 82     2     0     0   933372  1542944    2    0     2    0     0    0     0  13600  96823  5848  14  5 81     2     0     0   933372  1540620    1    0     6    0     0    0     0  13216  90131  5740  22  5 73 db02#[/]

几乎立竿见影，删除这个进程后，系统的运行队列（r）几乎没有了，和阻塞队列（b）一下子消失了，操作系统的page in导致的页交换骤减到一个非常正常的可接受值，系统的可用内存升高到free*page size=1544205*4096=6325063680 byte）左右

再次使用top，可以看到：

db02#[/]top   。。。。。。 Memory: 7744752K (2796296K) real, 13421176K (4155264K) virtual, 6105600K free  Page# 1/36 。。。。。

系统的可用内存确实已经升高到6G左右了。

再来看看CPU的使用：

db02#[/]sar -u 2 10 HP-UX db02 B.11.11 U 9000/800    03/04/05   16:39:31    %usr    %sys    %wio   %idle 16:39:33      15       8      20      56 16:39:35      14       7      20      59 16:39:37      12       4      18      66 16:39:39      20       5      22      54 16:39:41      17       8      12      63 16:39:43      11       4      13      73 16:39:45      15       4      17      64 16:39:47      13       4      13      70 16:39:49      17       9      22      51 16:39:51      14       5      15      65   Average       15       6      17      62 db02#[/]

我们看到，CPU的idel平均值（%idle）在62％，而系统的wait io（%wio）的平均值在17％，这已经是一个非常理想的状态。系统性能恢复正常了。

后记

       总结下来，解决这个问题的关键其实就在于如何释放掉那个操作系统不能正常回收而浪费的（Oracle异常占用的）6G的内存。虽然，可以通过shminfo找到进程号杀死进程，也可以通过重起主机解决（当然，很少有人选择后者，尤其是现网数据库），但是继续跟踪这个问题的话，我们发现了这是一个HP MC 11.15的bug，需要通过打PATCH PHSS_28926来解决这种内存不能正常回收的问题。

       最后请记住，在一个安装在HP MC 11.15环境下的ORACLE RAC系统中，要想正常使用数据库，必须至少安装3个相应的HP MC 11.15的patch：

PHSS_28926

PHSS_30370

PHSS_29096