OOM-Killer 的取证分析

Question

Ubuntu 的 Out-Of-Memory Killer 对我的服务器造成了严重破坏，悄悄地暗杀了我的应用程序、sendmail、apache 和其他应用程序。

我已经设法了解了 OOM 杀手是什么，以及它的“坏”规则。虽然我的机器很小，但我的应用程序更小，通常只有一半的物理内存在使用，更不用说交换空间了，所以我很惊讶。我试图找出罪魁祸首，但我不知道如何阅读 OOM-Killer 日志。

任何人都可以指点我如何阅读日志中的数据的教程（什么是ve，free和gen？），或者帮我解析这些日志？

Apr 20 20:03:27 EL135 kernel: kill_signal(13516.0): selecting to kill, queued 0, seq 1, exc 2326 0 goal 2326 0...
Apr 20 20:03:27 EL135 kernel: kill_signal(13516.0): task ebb0c6f0, thg d33a1b00, sig 1
Apr 20 20:03:27 EL135 kernel: kill_signal(13516.0): selected 1, signalled 1, queued 1, seq 1, exc 2326 0 red 61795 745
Apr 20 20:03:27 EL135 kernel: kill_signal(13516.0): selecting to kill, queued 0, seq 2, exc 122 0 goal 383 0...
Apr 20 20:03:27 EL135 kernel: kill_signal(13516.0): task ebb0c6f0, thg d33a1b00, sig 1
Apr 20 20:03:27 EL135 kernel: kill_signal(13516.0): selected 1, signalled 1, queued 1, seq 2, exc 383 0 red 61795 745
Apr 20 20:03:27 EL135 kernel: kill_signal(13516.0): task ebb0c6f0, thg d33a1b00, sig 2
Apr 20 20:03:27 EL135 kernel: OOM killed process watchdog (pid=14490, ve=13516) exited, free=43104 gen=24501.
Apr 20 20:03:27 EL135 kernel: OOM killed process tail (pid=4457, ve=13516) exited, free=43104 gen=24502.
Apr 20 20:03:27 EL135 kernel: OOM killed process ntpd (pid=10816, ve=13516) exited, free=43104 gen=24503.
Apr 20 20:03:27 EL135 kernel: OOM killed process tail (pid=27401, ve=13516) exited, free=43104 gen=24504.
Apr 20 20:03:27 EL135 kernel: OOM killed process tail (pid=29009, ve=13516) exited, free=43104 gen=24505.
Apr 20 20:03:27 EL135 kernel: OOM killed process apache2 (pid=10557, ve=13516) exited, free=49552 gen=24506.
Apr 20 20:03:27 EL135 kernel: OOM killed process apache2 (pid=24983, ve=13516) exited, free=53117 gen=24507.
Apr 20 20:03:27 EL135 kernel: OOM killed process apache2 (pid=29129, ve=13516) exited, free=68493 gen=24508.
Apr 20 20:03:27 EL135 kernel: OOM killed process sendmail-mta (pid=941, ve=13516) exited, free=68803 gen=24509.
Apr 20 20:03:27 EL135 kernel: OOM killed process tail (pid=12418, ve=13516) exited, free=69330 gen=24510.
Apr 20 20:03:27 EL135 kernel: OOM killed process python (pid=22953, ve=13516) exited, free=72275 gen=24511.
Apr 20 20:03:27 EL135 kernel: OOM killed process apache2 (pid=6624, ve=13516) exited, free=76398 gen=24512.
Apr 20 20:03:27 EL135 kernel: OOM killed process python (pid=23317, ve=13516) exited, free=94285 gen=24513.
Apr 20 20:03:27 EL135 kernel: OOM killed process tail (pid=29030, ve=13516) exited, free=95339 gen=24514.
Apr 20 20:03:28 EL135 kernel: OOM killed process apache2 (pid=20583, ve=13516) exited, free=101663 gen=24515.
Apr 20 20:03:28 EL135 kernel: OOM killed process logger (pid=12894, ve=13516) exited, free=101694 gen=24516.
Apr 20 20:03:28 EL135 kernel: OOM killed process bash (pid=21119, ve=13516) exited, free=101849 gen=24517.
Apr 20 20:03:28 EL135 kernel: OOM killed process atd (pid=991, ve=13516) exited, free=101880 gen=24518.
Apr 20 20:03:28 EL135 kernel: OOM killed process apache2 (pid=14649, ve=13516) exited, free=102748 gen=24519.
Apr 20 20:03:28 EL135 kernel: OOM killed process grep (pid=21375, ve=13516) exited, free=132167 gen=24520.
Apr 20 20:03:57 EL135 kernel: kill_signal(13516.0): selecting to kill, queued 0, seq 4, exc 4215 0 goal 4826 0...
Apr 20 20:03:57 EL135 kernel: kill_signal(13516.0): task ede29370, thg df98b880, sig 1
Apr 20 20:03:57 EL135 kernel: kill_signal(13516.0): selected 1, signalled 1, queued 1, seq 4, exc 4826 0 red 189481 331
Apr 20 20:03:57 EL135 kernel: kill_signal(13516.0): task ede29370, thg df98b880, sig 2
Apr 20 20:04:53 EL135 kernel: kill_signal(13516.0): selecting to kill, queued 0, seq 5, exc 3564 0 goal 3564 0...
Apr 20 20:04:53 EL135 kernel: kill_signal(13516.0): task c6c90110, thg cdb1a100, sig 1
Apr 20 20:04:53 EL135 kernel: kill_signal(13516.0): selected 1, signalled 1, queued 1, seq 5, exc 3564 0 red 189481 331
Apr 20 20:04:53 EL135 kernel: kill_signal(13516.0): task c6c90110, thg cdb1a100, sig 2
Apr 20 20:07:14 EL135 kernel: kill_signal(13516.0): selecting to kill, queued 0, seq 6, exc 8071 0 goal 8071 0...
Apr 20 20:07:14 EL135 kernel: kill_signal(13516.0): task d7294050, thg c03f42c0, sig 1
Apr 20 20:07:14 EL135 kernel: kill_signal(13516.0): selected 1, signalled 1, queued 1, seq 6, exc 8071 0 red 189481 331
Apr 20 20:07:14 EL135 kernel: kill_signal(13516.0): task d7294050, thg c03f42c0, sig 2

Watchdog 是看门狗任务，即空闲；日志中没有任何内容表明它已经做了好几天的事情。它的工作是在一个应用程序死掉时重新启动它，所以有点讽刺的是它是第一个被杀死的。

Tail 正在监视一些日志文件。不太可能疯狂地消耗内存。

apache 网络服务器只为一个小老太太提供页面，她只在星期天用它去教堂，几个开发人员在床上睡着了，几个星期没有访问网站上的页面。它可能拥有的唯一流量来自端口扫描器；所有内容都受密码保护，没有从任何地方链接，所以没有蜘蛛感兴趣。

Python 正在运行两个独立的自定义应用程序。日志中没有任何内容表明他们没有像往常一样嗡嗡作响。其中一个是相对较新的实现，这使怀疑＃1。它没有任何重要的数据结构，通常只使用总物理 RAW 的 8% 左右。从那以后它就没有行为不端了。

grep 是第 2 号嫌疑犯，也是我想认罪的那个，因为它是一次性命令。该命令（将 grep -r 的输出通过管道传送到另一个 grep）已在至少 30 分钟前启动，并且它仍在运行的事实令人怀疑。但是，我没想到 grep 会使用大量内存。OOM杀手花了一段时间才找到它，这表明它并没有发疯，但是OOM杀手一旦被杀死就停止了，这表明它可能是一个记忆猪，最终满足了OOM杀手的嗜血.

Answer 1

我是 ServerFault 新手，刚刚看到这篇文章。尽管它很旧，但它似乎又重新出现在队列的前面。让我们把这个可怕的家伙放到床上吧？

首先，我对这个主题很感兴趣，因为我正在优化 RAM 有限的系统，以便以安全的方式运行许多用户进程。

我认为此日志中的错误消息指的是 OpenVZ Linux 容器。

“ve”是一个虚拟环境，在 OpenVZ 中也称为容器。每个容器都有一个 ID，您看到的数字就是该 ID。更多相关内容请点击这里：

https://openvz.org/Container

术语“空闲”是指当时的空闲内存（以字节为单位）。您可以看到随着进程被终止，可用内存逐渐增加。

我对“gen”这个词有点不确定。我相信这是指世代。也就是说，它从 1 开始，容器中每生成一个进程就加 1。因此，对于您的系统，自启动以来似乎执行了 24K+ 个进程。如果我错了，请纠正我。这应该很容易测试。

至于为什么它杀死了进程，那是因为你的 OOM Killer 配置。它试图将可用内存恢复到预期数量（看起来是 128 Kb）。Oracle 有一篇很好的文章，介绍了如何将其配置为您可能更喜欢的内容：

http://www.oracle.com/technetwork/articles/servers-storage-dev/oom-killer-1911807.html

此外，如果您想查看每个容器的内存配置，请查看以下内容：

https://openvz.org/Setting_UBC_parameters