Linux 服务器内存不足，除了 ssh 和交换区未使用外，其他一切都停止了

Question

几天前，我的 linux apache 服务器内存不足。服务器是 xen 来宾。服务器杀死了除 ssh 之外的所有进程（甚至是 cron、monit、syslog）。

在内存耗尽前一分钟，我的一个脚本保存了各种命令的输出。这是输出：

# free -m
             total       used       free     shared    buffers     cached
Mem:          2003       1866        137          0          3       1159
-/+ buffers/cache:        703       1300
Swap:          511          0        511

# vmstat 1 2
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
 2  1    144 140944   4192 1186964    0    0     0     0    1    0  1  0 98  1
 3  1    144 142816   3704 1186896    0    0  4188 10132 3242 3242  0 19 59 22

# pidstat -dru 1 3
Linux 2.6.39-linode33 (web1)    09/10/11        _i686_

01:07:15          PID   %user %system    %CPU   CPU  Command
01:07:16          271    0.00   10.78   10.78     0  kswapd0
01:07:16         9871    0.00  100.00  100.00     1  flush-0:17
01:07:16        13082    0.00    1.96    1.96     0  apache2
01:07:16        15100    0.98    5.88    6.86     0  rm
01:07:16        15250    0.00    0.98    0.98     0  pidstat

01:07:15          PID  minflt/s  majflt/s     VSZ    RSS   %MEM  Command
01:07:16        13082      1.96      0.98   62872  29720   1.45  apache2
01:07:16        15250    224.51      0.00    1704    636   0.03  pidstat

01:07:15          PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
01:07:16        13082     78.43      7.84      0.00  apache2
01:07:16        15100   1317.65      0.00      0.00  rm
01:07:16        15250      3.92      0.00      0.00  pidstat

01:07:16          PID   %user %system    %CPU   CPU  Command
01:07:17            3    0.00    0.99    0.99     0  ksoftirqd/0
01:07:17           12    0.00    0.99    0.99     2  ksoftirqd/2
01:07:17          271    0.00    1.98    1.98     2  kswapd0
01:07:17         9871    0.00  100.00  100.00     1  flush-0:17
01:07:17        15100    0.00   17.82   17.82     2  rm
01:07:17        15232   17.82    0.99   18.81     0  apache2
01:07:17        15250    0.99    1.98    2.97     0  pidstat
01:07:17        19944    0.00    0.99    0.99     0  kworker/0:2

01:07:16          PID  minflt/s  majflt/s     VSZ    RSS   %MEM  Command
01:07:17        15232    298.02      0.00   63096  12820   0.62  apache2
01:07:17        15250    231.68      0.00    1704    664   0.03  pidstat

01:07:16          PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
01:07:17        15100   4261.39      0.00      0.00  rm
01:07:17        15232      3.96      7.92      0.00  apache2
01:07:17        15250     11.88      0.00      0.00  pidstat

01:07:17          PID   %user %system    %CPU   CPU  Command
01:07:18          271    0.00   11.11   11.11     2  kswapd0
01:07:18         9871    0.00  100.00  100.00     1  flush-0:17
01:07:18        15100    1.01   27.27   28.28     2  rm
01:07:18        15250    0.00    1.01    1.01     0  pidstat
01:07:18        19944    0.00    1.01    1.01     0  kworker/0:2

01:07:17          PID  minflt/s  majflt/s     VSZ    RSS   %MEM  Command
01:07:18        15250    229.29      0.00    1704    664   0.03  pidstat

01:07:17          PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
01:07:18        15100   4230.30      0.00      0.00  rm
01:07:18        15250     16.16      4.04      0.00  pidstat

Average:          PID   %user %system    %CPU   CPU  Command
Average:            3    0.00    0.33    0.33     -  ksoftirqd/0
Average:           12    0.00    0.33    0.33     -  ksoftirqd/2
Average:          271    0.00    7.95    7.95     -  kswapd0
Average:         9871    0.00  100.00  100.00     -  flush-0:17
Average:        13082    0.00    0.66    0.66     -  apache2
Average:        15100    0.66   16.89   17.55     -  rm
Average:        15232    5.96    0.33    6.29     -  apache2
Average:        15250    0.33    1.32    1.66     -  pidstat
Average:        19944    0.00    0.66    0.66     -  kworker/0:2

Average:          PID  minflt/s  majflt/s     VSZ    RSS   %MEM  Command
Average:        13082      0.66      0.33   62872  29720   1.45  apache2
Average:        15232     99.67      0.00   62927  12456   0.61  apache2
Average:        15250    228.48      0.00    1704    655   0.03  pidstat

Average:          PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
Average:        13082     26.49      2.65      0.00  apache2
Average:        15100   3256.95      0.00      0.00  rm
Average:        15232      1.32      2.65      0.00  apache2
Average:        15250     10.60      1.32      0.00  pidstat

Monit 报告了这些统计数据（也是在内存耗尽前一分钟）：

System 'local'
  status                            Resource limit matched
  monitoring status                 monitored
  load average                      [3.57] [2.63] [1.30]
  cpu                               0.5%us 18.5%sy 37.1%wa
  memory usage                      726464 kB [35.4%]
  swap usage                        148 kB [0.0%]
  data collected                    Sat Sep 10 01:06:06 2011

以下是 kern.log 中记录的摘录：

Sep 10 01:07:31 web1 kernel: Out of memory: Kill process 2190 (portmap) score 1 or sacrifice child
Sep 10 01:07:31 web1 kernel: Killed process 2190 (portmap) total-vm:1820kB, anon-rss:100kB, file-rss:360kB
Sep 10 01:07:31 web1 kernel: apache2 invoked oom-killer: gfp_mask=0xd0, order=1, oom_adj=0, oom_score_adj=0
Sep 10 01:07:31 web1 kernel: Pid: 31143, comm: apache2 Tainted: G        W   2.6.39-linode33 #5
Sep 10 01:07:31 web1 kernel: Call Trace:
Sep 10 01:07:31 web1 kernel: [<c0185c10>] ? T.663+0x80/0xd0
Sep 10 01:07:31 web1 kernel: [<c0185cbe>] ? T.661+0x5e/0x160
Sep 10 01:07:31 web1 kernel: [<c013d8ac>] ? has_capability_noaudit+0xc/0x20
Sep 10 01:07:31 web1 kernel: [<c0185a1c>] ? oom_badness+0xdc/0x130
Sep 10 01:07:31 web1 kernel: [<c0185f76>] ? out_of_memory+0x1b6/0x2f0
Sep 10 01:07:31 web1 kernel: [<c0189715>] ? __alloc_pages_nodemask+0x6b5/0x6d0
Sep 10 01:07:31 web1 kernel: [<c0131c35>] ? dup_task_struct+0x55/0x140
Sep 10 01:07:31 web1 kernel: [<c0132728>] ? copy_process+0x88/0xb80
Sep 10 01:07:31 web1 kernel: [<c013326f>] ? do_fork+0x4f/0x290
Sep 10 01:07:31 web1 kernel: [<c0156084>] ? getnstimeofday+0x44/0x110
Sep 10 01:07:31 web1 kernel: [<c010f510>] ? sys_clone+0x30/0x40
Sep 10 01:07:31 web1 kernel: [<c06900cd>] ? ptregs_clone+0x15/0x48
Sep 10 01:07:31 web1 kernel: [<c068f7b1>] ? syscall_call+0x7/0xb
Sep 10 01:07:31 web1 kernel: [<c0680000>] ? sctp_icmp_proto_unreachable+0x20/0xc0
Sep 10 01:07:31 web1 kernel: Mem-Info:
Sep 10 01:07:31 web1 kernel: DMA per-cpu:
Sep 10 01:07:31 web1 kernel: CPU    0: hi:    0, btch:   1 usd:   0
Sep 10 01:07:31 web1 kernel: CPU    1: hi:    0, btch:   1 usd:   0
Sep 10 01:07:31 web1 kernel: CPU    2: hi:    0, btch:   1 usd:   0
Sep 10 01:07:31 web1 kernel: CPU    3: hi:    0, btch:   1 usd:   0
Sep 10 01:07:31 web1 kernel: Normal per-cpu:
Sep 10 01:07:31 web1 kernel: CPU    0: hi:  186, btch:  31 usd:  36
Sep 10 01:07:31 web1 kernel: CPU    1: hi:  186, btch:  31 usd:   0
Sep 10 01:07:31 web1 kernel: CPU    2: hi:  186, btch:  31 usd:  18
Sep 10 01:07:31 web1 kernel: CPU    3: hi:  186, btch:  31 usd:   0
Sep 10 01:07:31 web1 kernel: HighMem per-cpu:
Sep 10 01:07:31 web1 kernel: CPU    0: hi:  186, btch:  31 usd:  54
Sep 10 01:07:31 web1 kernel: CPU    1: hi:  186, btch:  31 usd:   0
Sep 10 01:07:31 web1 kernel: CPU    2: hi:  186, btch:  31 usd:   0
Sep 10 01:07:31 web1 kernel: CPU    3: hi:  186, btch:  31 usd:  22
Sep 10 01:07:31 web1 kernel: active_anon:7174 inactive_anon:3515 isolated_anon:0
Sep 10 01:07:31 web1 kernel: active_file:156159 inactive_file:133601 isolated_file:0
Sep 10 01:07:31 web1 kernel: unevictable:0 dirty:12 writeback:0 unstable:0
Sep 10 01:07:31 web1 kernel: free:39375 slab_reclaimable:166268 slab_unreclaimable:3027
Sep 10 01:07:31 web1 kernel: mapped:1913 shmem:8277 pagetables:95 bounce:0
Sep 10 01:07:31 web1 kernel: DMA free:2908kB min:88kB low:108kB high:132kB active_anon:0kB inactive_anon:0kB active_file:292kB inactive_file:296kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15808kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:988kB slab_unreclaimable:132kB kernel_stack:72kB pagetables:20kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:11075 all_unreclaimable? yes
Sep 10 01:07:31 web1 kernel: lowmem_reserve[]: 0 702 2008 2008
Sep 10 01:07:31 web1 kernel: Normal free:5376kB min:4004kB low:5004kB high:6004kB active_anon:0kB inactive_anon:0kB active_file:2316kB inactive_file:2264kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:719320kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:664084kB slab_unreclaimable:11976kB kernel_stack:512kB pagetables:360kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:84892 all_unreclaimable? yes
Sep 10 01:07:31 web1 kernel: lowmem_reserve[]: 0 0 10444 10444
Sep 10 01:07:31 web1 kernel: HighMem free:149216kB min:512kB low:2372kB high:4236kB active_anon:28696kB inactive_anon:14060kB active_file:622028kB inactive_file:531844kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:1336932kB mlocked:0kB dirty:48kB writeback:0kB mapped:7652kB shmem:33108kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
Sep 10 01:07:31 web1 kernel: lowmem_reserve[]: 0 0 0 0
Sep 10 01:07:31 web1 kernel: DMA: 231*4kB 126*8kB 21*16kB 4*32kB 2*64kB 1*128kB 1*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 2908kB
Sep 10 01:07:31 web1 kernel: Normal: 1310*4kB 18*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 5384kB
Sep 10 01:07:31 web1 kernel: HighMem: 18118*4kB 7805*8kB 836*16kB 27*32kB 1*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 149216kB
Sep 10 01:07:31 web1 kernel: 298087 total pagecache pages
Sep 10 01:07:31 web1 kernel: 35 pages in swap cache
Sep 10 01:07:31 web1 kernel: Swap cache stats: add 2601, delete 2566, find 2926/3087
Sep 10 01:07:31 web1 kernel: Free swap  = 524144kB
Sep 10 01:07:31 web1 kernel: Total swap = 524284kB
Sep 10 01:07:31 web1 kernel: 1050608 pages RAM
Sep 10 01:07:31 web1 kernel: 865282 pages HighMem
Sep 10 01:07:31 web1 kernel: 537706 pages reserved
Sep 10 01:07:31 web1 kernel: 7195 pages shared
Sep 10 01:07:31 web1 kernel: 468537 pages non-shared
Sep 10 01:07:31 web1 kernel: [ pid ]   uid  tgid total_vm      rss cpu oom_adj oom_score_adj name
Sep 10 01:07:31 web1 kernel: [ 1059]     0  1059      552      184   3     -17         -1000 udevd
Sep 10 01:07:31 web1 kernel: [ 2196]   104  2196      470      175   0       0             0 rpc.statd
Sep 10 01:07:31 web1 kernel: [ 2323]     0  2323     1044      575   2       0             0 syslog-ng
Sep 10 01:07:31 web1 kernel: [ 2334]     0  2334     1332      252   3     -17         -1000 sshd
Sep 10 01:07:31 web1 kernel: [ 2360]   101  2360     1047      303   3       0             0 ntpd
Sep 10 01:07:31 web1 kernel: [ 2426]     0  2426      425      125   0       0             0 getty
Sep 10 01:07:31 web1 kernel: [32223]     0 32223      523      220   0       0             0 cron
Sep 10 01:07:31 web1 kernel: [ 8378]     0  8378     3478      566   0       0             0 monit
Sep 10 01:07:31 web1 kernel: [31143]     0 31143    15446     2689   0       0             0 apache2
Sep 10 01:07:31 web1 kernel: [15030]     0 15030      606      228   2       0             0 cron
Sep 10 01:07:31 web1 kernel: [15034]     0 15034      622      248   3       0             0 sh
Sep 10 01:07:31 web1 kernel: [15100]     0 15100      429       58   2       0             0 rm
Sep 10 01:07:31 web1 kernel: Out of memory: Kill process 2196 (rpc.statd) score 1 or sacrifice child
Sep 10 01:07:31 web1 kernel: Killed process 2196 (rpc.statd) total-vm:1880kB, anon-rss:124kB, file-rss:576kB

另外，由于是凌晨 1 点，当时几乎没有 apache 连接。

如您所见，根本没有使用交换。仍然有相当多的空闲内存（根据 monit）。

有什么想法可以找出原因吗？

另外，根据pidstat，使用这么多CPU的“flush-0:17”是什么？

Answer 1

从日志输出来看，apache 正在尝试 malloc 一个非常大的分配。要找出原因，您可能需要查看您的 apache 设置并查看可以执行此操作的内容（您是否使用 mod_perl、mod_python 等）。如果你找不到这样的方法，你可以在 apache 前面放置一个像 nginx 这样的代理，然后 nginx 会记录哪个请求失败。如果你愿意，你可以在同一主机上运行 nginx，只需使用 limit 命令来限制 apache，这样它就会在调用 oom Killer 之前被杀死（让 nginx 继续运行，或 urlsnarf 等）。

刷新 PID 是处理同步 VFS 缓存缓冲区的内核线程。很可能与 rm 有关。您可以通过查找刷新线程及其为哪个设备工作并验证该设备 rm 正在工作来进行验证：

# ps axwwu | grep flush
root     21658  0.0  0.0      0     0 ?        S    21:33   0:00 [flush-8:16]
# ls -l /dev/ | grep 8 | grep 16
brw-rw----  1 root disk      8,  16 2011-09-13 13:53 sdb