Skip to content

Latest commit

 

History

History
815 lines (544 loc) · 40.6 KB

File metadata and controls

815 lines (544 loc) · 40.6 KB

十一、常见故障恢复

在前一章中,我们探讨了 Linux 服务器上存在的用户和系统限制。 我们了解了存在哪些限制,以及如何更改需要超过默认值的应用的值。

在本章中,我们将在资源耗尽的系统中使用故障排除技能。

报告的问题

今天的章节,就像其他章节一样,将以某人报告一个问题开始。 报告的问题是 Apache 不再运行在服务于公司博客blog.example.com的服务器上。

报告这个问题的系统管理员同事解释说,有人报告说博客宕掉了,当他登录到服务器时,他可以看到 Apache 不再运行了。 当时,我们的同伴不知道该怎么做才能继续下去,于是向我们寻求帮助。

Apache 真的倒下了吗?

当一个服务被报告为关闭时,我们应该做的第一件事就是验证它是否真的关闭了。 这实际上是我们的故障诊断流程中的为我们自己复制它步骤。 对于 Apache 这样的服务,我们还应该快速地验证它是否真的下降了。

根据我的经验,我经常听到有人说某个服务停止了,但实际上它并没有停止。 服务器可能有问题,但它不是技术上的故障。 up 或 down 之间的差异可以更改解决问题所需执行的故障排除步骤。

也就是说,对于这类问题,我总是执行的第一步是验证服务是否真的停止了,还是仅仅是服务没有响应。

为了验证 Apache 是否真的停止了,我们将使用ps命令。 如前所述,该命令将打印当前正在运行的进程的列表。 我们将此输出重定向到grep命令,以检查是否有httpd(Apache)服务的实例在运行:

# ps -elf | grep http
0 S root      2645  1974  0  80   0 - 28160 pipe_w 21:45 pts/0 00:00:00 grep --color=auto http

从上面的ps命令的输出中,我们可以看到没有名为httpd的进程在运行。 在正常情况下,我们预计至少会看到几行类似以下示例:

5 D apache    2383     1  0  80   0 - 115279 conges 20:58 ? 00:00:04 /usr/sbin/httpd -DFOREGROUND

由于在进程列表中没有发现进程,我们可以得出结论,Apache 实际上在这个系统上没有运行。 现在的问题是,为什么?

为什么它倒下了?

在简单地通过启动 Apache 服务来解决这个问题之前,我们首先要弄清楚为什么 Apache 服务没有运行。 这是一个称为根本原因分析(RCA)的过程,这是一个用于理解首先引起问题的原因的形式化过程。

下一章我们将对这一过程非常熟悉。 在本章中,我们将保持简单,重点关注为什么 Apache 不能运行。

我们首先要查看的地方之一是/var/log/httpd中的 Apache 日志。 在前面的章节中,我们在故障排除其他与 web 服务器相关的问题时了解了这些日志。 正如我们在前面的章节中看到的,应用和服务日志在确定服务发生了什么方面非常有帮助。

由于 Apache 不再运行,我们更感兴趣的是最近发生的几个事件。 如果服务遇到致命错误或停止,在日志文件的末尾应该有一条消息显示这一点。

因为我们只对最后几个事件感兴趣,所以我们将使用tail命令来显示error_log文件的最后 10 行。 error_log文件是要检查的第一个日志,因为它是最可能出现异常的地方:

# tail /var/log/httpd/error_log
[Sun Jun 21 20:51:32.889455 2015] [mpm_prefork:notice] [pid 2218] AH00163: Apache/2.4.6  PHP/5.4.16 configured -- resuming normal operations
[Sun Jun 21 20:51:32.889690 2015] [core:notice] [pid 2218] AH00094: Command line: '/usr/sbin/httpd -D FOREGROUND'
[Sun Jun 21 20:51:33.892170 2015] [mpm_prefork:error] [pid 2218] AH00161: server reached MaxRequestWorkers setting, consider raising the MaxRequestWorkers setting
[Sun Jun 21 20:53:42.577787 2015] [mpm_prefork:notice] [pid 2218] AH00170: caught SIGWINCH, shutting down gracefully [Sun Jun 21 20:53:44.677885 2015] [core:notice] [pid 2249] SELinux policy enabled; httpd running as context system_u:system_r:httpd_t:s0
[Sun Jun 21 20:53:44.678919 2015] [suexec:notice] [pid 2249] AH01232: suEXEC mechanism enabled (wrapper: /usr/sbin/suexec)
[Sun Jun 21 20:53:44.703088 2015] [auth_digest:notice] [pid 2249] AH01757: generating secret for digest authentication ...
[Sun Jun 21 20:53:44.704046 2015] [lbmethod_heartbeat:notice] [pid 2249] AH02282: No slotmem from mod_heartmonitor
[Sun Jun 21 20:53:44.732504 2015] [mpm_prefork:notice] [pid 2249] AH00163: Apache/2.4.6  PHP/5.4.16 configured -- resuming normal operations
[Sun Jun 21 20:53:44.732568 2015] [core:notice] [pid 2249] AH00094: Command line: '/usr/sbin/httpd -D FOREGROUND'

error_log文件内容中,我们可以看到相当多有趣的消息。 让我们快速浏览一下,看看一些更多信息的日志条目。

[Sun Jun 21 20:53:42.577787 2015] [mpm_prefork:notice] [pid 2218] AH00170: caught SIGWINCH, shutting down gracefully

前面一行显示 Apache 进程在Sunday, Jun 21上的20:53上被关闭。 我们可以看到这个错误消息清楚地说明了shutting down gracefully。 然而,接下来的几行似乎表明 Apache 服务只在2秒后就恢复了:

[Sun Jun 21 20:53:44.677885 2015] [core:notice] [pid 2249] SELinux policy enabled; httpd running as context system_u:system_r:httpd_t:s0
[Sun Jun 21 20:53:44.678919 2015] [suexec:notice] [pid 2249] AH01232: suEXEC mechanism enabled (wrapper: /usr/sbin/suexec)
[Sun Jun 21 20:53:44.703088 2015] [auth_digest:notice] [pid 2249] AH01757: generating secret for digest authentication ...
[Sun Jun 21 20:53:44.704046 2015] [lbmethod_heartbeat:notice] [pid 2249] AH02282: No slotmem from mod_heartmonitor
[Sun Jun 21 20:53:44.732504 2015] [mpm_prefork:notice] [pid 2249] AH00163: Apache/2.4.6  PHP/5.4.16 configured -- resuming normal operations

shutdown 日志项显示的是进程 id2218,而前面五行显示的是进程 id2249。 第 5 行也是resuming normal operations。 这四个消息似乎表明 Apache 进程只是重新启动了。 最有可能的是,这是 Apache 的一次优雅的重启。

Apache 的优雅重启是在配置修改期间执行的一项相当常见的任务。 这是一种重新启动 Apache 进程而不会使其完全关闭并影响 web 服务的方法。

[Sun Jun 21 20:53:44.732568 2015] [core:notice] [pid 2249] AH00094: Command line: '/usr/sbin/httpd -D FOREGROUND'

然而,这 10 行代码告诉我们的最有趣的事情是,Apache 打印的最后一个日志只不过是一个通知。 当 Apache 优雅地停止时,它在error_log文件中记录一条消息,表明它正在停止。

由于 Apache 进程不再运行,并且没有日志记录显示它被正常或不正常地关闭,我们可以得出结论,不管 Apache 没有运行的原因是什么,它都没有正常关闭。

如果有人通过使用apachectlsystemctl命令关闭服务,我们将期望看到与前面示例中讨论的消息类似的消息。 由于日志文件的最后一行没有显示关闭消息,我们只能假设该进程在异常情况下被杀死或终止。

现在,问题是什么可能导致 Apache 进程以这种异常方式终止?

一个可能提供关于 Apache 发生了什么的线索的地方是 systemd 设施,因为 Red Hat Enterprise Linux 7 服务,如 Apache,已经被转移到 systemd。 在启动时,systemd工具将启动配置为启动的任何服务。

systemd启动的进程被终止时,该活动被systemd捕获。 根据进程终止后发生的情况,我们可以看到systemd是否使用systemctl命令捕获了该事件:

# systemctl status httpd
httpd.service - The Apache HTTP Server
 Loaded: loaded (/usr/lib/systemd/system/httpd.service; enabled)
 Active: failed (Result: timeout) since Fri 2015-06-26 21:21:38 UTC; 22min ago
 Process: 2521 ExecStop=/bin/kill -WINCH ${MAINPID} (code=exited, status=0/SUCCESS)
 Process: 2249 ExecStart=/usr/sbin/httpd $OPTIONS -DFOREGROUND (code=killed, signal=KILL)
 Main PID: 2249 (code=killed, signal=KILL)
 Status: "Total requests: 1649; Current requests/sec: -1.29; Current traffic:   0 B/sec"

Jun 21 20:53:44 blog.example.com systemd[1]: Started The Apache HTTP Server.
Jun 26 21:12:55 blog.example.com systemd[1]: httpd.service: main process exited, code=killed, status=9/KILL
Jun 26 21:21:20 blog.example.com systemd[1]: httpd.service stopping timed out. Killing.
Jun 26 21:21:38 blog.example.com systemd[1]: Unit httpd.service entered failed state.

命令的输出显示了相当多的信息。 由于我们在前面的章节中已经介绍了相当多的内容,所以我将跳到输出的部分,这些部分将告诉我们 Apache 服务发生了什么。

下面这两行看起来很有趣:

 Process: 2249 ExecStart=/usr/sbin/httpd $OPTIONS -DFOREGROUND (code=killed, signal=KILL)
 Main PID: 2249 (code=killed, signal=KILL)

在这两行中,我们可以看到进程 id2249,我们也在error_log文件中看到。 这是在Sunday, June 21上启动的 Apache 实例的进程 id。 我们还可以从这些线中看到,过程2249被杀死了。 这似乎表明有人或什么东西杀死了我们的 Apache 服务:

Jun 21 20:53:44 blog.example.com systemd[1]: Started The Apache HTTP Server.
Jun 26 21:12:55 blog.example.com systemd[1]: httpd.service: main process exited, code=killed, status=9/KILL
Jun 26 21:21:20 blog.example.com systemd[1]: httpd.service stopping timed out. Killing.
Jun 26 21:21:38 blog.example.com systemd[1]: Unit httpd.service entered failed state.

如果我们看一下状态输出的最后几行,我们可以看到systemd设备捕获的事件。 我们可以看到的第一个事件是 Apache 服务在June 21上从20:53启动。 这并不奇怪,因为它与我们在error_log中看到的信息相关。

然而,最后三行显示 Apache 进程随后在June 2621:21上被杀死。 不幸的是,这些事件并不能确切地显示为什么 Apache 进程被杀死或者是谁杀死了它。 它只告诉我们阿帕奇被杀的确切时间。 这也表明不太可能是systemd设施停止了 Apache 服务。

那时候还发生了什么事?

由于我们无法从 Apache 日志或systemctl status中确定原因,我们将需要继续挖掘,以了解其他可能导致该服务死亡的原因。

# date
Sun Jun 28 18:32:33 UTC 2015

由于 26 日是几天前,我们有一些有限的地方来寻找更多的信息。 我们可以查看的一个地方是/var/log/messages日志文件。 正如我们在前面的章节中发现的,messages日志包含了来自系统中许多不同设施的相当多的不同信息。 如果有一个地方可以告诉我们当时的系统发生了什么,那就是那里。

搜索消息日志

messages日志非常大,其中有许多日志条目:

# wc -l /var/log/messages
21683 /var/log/messages

因此,我们需要过滤与我们的问题不相关或在我们的问题发生期间不相关的日志消息。 我们可以做的第一件事就是在日志中搜索 Apache 停止的那天的消息:June 26

# tail -1 /var/log/messages
Jun 28 20:44:01 localhost systemd: Started Session 348 of user vagrant.

通过前面提到的tail命令,我们可以看到/var/log/messages文件中的消息具有日期、主机名、进程和消息的格式。 日期字段是三个字母组成的月份,然后是日期和 24 小时的时间戳。

因为我们的问题发生在 6 月 26 日,所以我们可以在这个日志文件中搜索字符串“Jun 26”的任何实例。 这应该能提供 26 日写的所有信息:

# grep -c "Jun 26" /var/log/messages
17864

显然,这仍然是相当多的日志消息,太多了,无法全部读取。 考虑到这个数字,我们需要过滤更多的消息,也许通过过程:

# grep "Jun 26" /var/log/messages | cut -d\  -f1,2,5 | sort -n | uniq -c | sort -nk 1 | tail
 39 Jun 26 journal:
 56 Jun 26 NetworkManager:
 76 Jun 26 NetworkManager[582]:
 76 Jun 26 NetworkManager[588]:
 78 Jun 26 NetworkManager[580]:
 79 Jun 26 systemd-logind:
 110 Jun 26 systemd[1]:
 152 Jun 26 NetworkManager[574]:
 1684 Jun 26 systemd:
 15077 Jun 26 kernel:

前面的代码通常称为bash一行程序。 这通常是一系列命令,它们将输出重定向到另一个命令,以提供一个命令本身无法执行或生成的函数或输出。 在本例中,我们有一个一行程序,它显示在 6 月 26 日哪个进程的日志记录最多。

分解这个有用的一行程序

上面提到的一行程序一开始有些复杂,但是一旦我们分解了这个一行程序,它就变得更容易理解了。 这是一个非常有用的一行程序,因为它使在日志文件中识别趋势变得非常容易。

让我们分解这个一行代码来更好地理解它在做什么:

# grep "Jun 26" /var/log/messages | cut -d\  -f1,2,5 | sort | uniq -c | sort -nk 1 | tail

我们已经知道第一个命令的作用; 它只是在/var/log/messages文件中搜索字符串“Jun 26”的任何实例。 其他的命令是我们之前没有涉及到的,但是它们可以是有用的命令。

cut 命令

这个一行程序中的cut命令用于读取grep命令的输出,并只打印每行的特定部分。 要理解它是如何工作的,我们应该首先运行以cut命令结尾的一行程序:

# grep "Jun 26" /var/log/messages | cut -d\  -f1,2,5
Jun 26 systemd:
Jun 26 systemd:
Jun 26 systemd:
Jun 26 systemd:
Jun 26 systemd:
Jun 26 systemd:
Jun 26 systemd:
Jun 26 systemd:
Jun 26 systemd:
Jun 26 systemd:

前面的cut命令通过指定分隔符并通过该分隔符截断输出来工作。

分隔符是一个字符,用于将行分解为多个字段; 我们可以用–d标志指定它。 在前面的例子中,–d标志后面跟着“\”; 反斜杠是一个转义字符,后面跟着一个空格。 这告诉cut命令使用单个空格字符作为分隔符。

–f标志用于指定应该显示的fields。 这些字段是分隔符之间的文本字符串。

例如,让我们看看下面的命令:

$ echo "Apples:Bananas:Carrots:Dried Cherries" | cut -d: -f1,2,4
Apples:Bananas:Dried Cherries

这里,我们指定“:”字符作为cut的分隔符。 我们还指定它应该打印第一个、第二个和第四个字段。 这产生了印刷苹果(第一块地)、香蕉(第二块地)和干樱桃(第四块地)的效果。 第三个字段 carrot 从输出中被省略。 这是因为我们没有明确地告诉cut命令打印第三个字段。

现在我们知道了cut是如何工作的,让我们看看它是如何处理messages日志条目的。

以下是一条日志消息的示例:

Jun 28 21:50:01 localhost systemd: Created slice user-0.slice.

当我们在一行程序中执行cut命令时,我们明确地告诉它只打印第一个、第二个和第五个字段:

# grep "Jun 26" /var/log/messages | cut -d\  -f1,2,5
Jun 26 systemd:

通过在cut命令中指定一个空格字符作为分隔符,可以看到这会导致cut只打印每个日志条目中的月、日和程序。 就其本身而言,这似乎不是很有用,但随着我们继续研究这个一行程序,cut 提供的功能将是至关重要的。

排序命令

下一个命令sort是,实际上在这个一行程序中使用了两次:

# grep "Jun 26" /var/log/messages | cut -d\  -f1,2,5 | sort | head
Jun 26 audispd:
Jun 26 audispd:
Jun 26 audispd:
Jun 26 audispd:
Jun 26 audispd:
Jun 26 auditd[539]:
Jun 26 auditd[539]:
Jun 26 auditd[542]:
Jun 26 auditd[542]:
Jun 26 auditd[548]:

这个命令的操作实际上非常简单。 这个一行程序中的sort命令接受cut命令的输出并对其排序(排序)。

为了更好地解释这一点,让我们看看下面的例子:

# cat /var/tmp/fruits.txt 
Apples
Dried Cherries
Carrots
Bananas

上面的文件又有几个水果,这次,它们不是按字母顺序排列的。 但是,如果我们使用sort命令来读取这个文件,这些水果的顺序将会改变:

# sort /var/tmp/fruits.txt 
Apples
Bananas
Carrots
Dried Cherries

正如我们所看到的,不管水果在文件中是如何列出的,顺序现在是按字母顺序排列的。 sort的优点是它可以用几种不同的方式对文本进行排序。 事实上,在一行代码中sort的第二个实例中,我们也使用–n标志对文本进行数字排序:

# cat /var/tmp/numbers.txt
10
23
2312
23292
1212
129191
# sort -n /var/tmp/numbers.txt 
10
23
1212
2312
23292
129191

uniq 命令

我们的一行程序包含sort命令的原因只是为了将输入发送到uniq -c:

# grep "Jun 26" /var/log/messages | cut -d\  -f1,2,5 | sort | uniq -c | head
 5 Jun 26 audispd:
 2 Jun 26 auditd[539]:
 2 Jun 26 auditd[542]:
 3 Jun 26 auditd[548]:
 2 Jun 26 auditd[550]:
 2 Jun 26 auditd[553]:
 15 Jun 26 augenrules:
 38 Jun 26 avahi-daemon[573]:
 19 Jun 26 avahi-daemon[579]:
 19 Jun 26 avahi-daemon[581]:

可以使用uniq命令识别匹配的行,并在一个惟一的行中显示这些行。 为了更好地理解这一点,让我们看看下面的例子:

$ cat /var/tmp/duplicates.txt 
Apple
Apple
Apple
Apple
Banana
Banana
Banana
Carrot
Carrot

我们的示例文件“duplicates.txt”包含多个重复的行。 当我们使用uniq读取这个文件时,我们将只看到每一行:

$ uniq /var/tmp/duplicates.txt 
Apple
Banana
Carrot

这可能有些用处; 然而,我发现使用–c标志,输出会更有用:

$ uniq -c /var/tmp/duplicates.txt 
 4 Apple
 3 Banana
 2 Carrot

使用–c标志,uniq命令将计算它找到每一行的次数。 在这里,我们可以看到有四行写着 Apple 这个词。 因此,uniq命令在单词 Apple 之前打印数字 4,以表示这一行有四个实例:

$ cat /var/tmp/duplicates.txt 
Apple
Apple
Orange
Apple
Apple
Banana
Banana
Banana
Carrot
Carrot
$ uniq -c /var/tmp/duplicates.txt 
 2 Apple
 1 Orange
 2 Apple
 3 Banana
 2 Carrot

uniq命令的一个警告是,为了获得准确的计数,每个实例需要紧接另一个实例。 您可以看到,当我们在 Apple 行组之间添加单词 Orange 时会发生什么。

把它们都绑在一起

如果我们再看一下我们的命令,我们现在可以更好地理解它在做什么:

# grep "Jun 26" /var/log/messages | cut -d\  -f1,2,5 | sort | uniq -c | sort -n | tail
 39 Jun 26 journal:
 56 Jun 26 NetworkManager:
 76 Jun 26 NetworkManager[582]:
 76 Jun 26 NetworkManager[588]:
 78 Jun 26 NetworkManager[580]:
 79 Jun 26 systemd-logind:
 110 Jun 26 systemd[1]:
 152 Jun 26 NetworkManager[574]:
 1684 Jun 26 systemd:
 15077 Jun 26 kernel:

上面的命令将过滤并打印/var/log/messages中与字符串“Jun 26”匹配的所有日志消息。 然后输出将被发送到cut命令,该命令打印每一行的月、日和进程。 然后将此输出发送到sort命令,将输出排列成相互匹配的组。 然后将排序后的输出发送到uniq –c,它计算每行出现的次数,并打印带有计数的唯一行。

从那里,我们添加另一个sort以按uniq添加的数字排序输出,并添加tail以将输出缩短到最后 10 行。

那么,这句俏皮话到底告诉了我们什么呢? 它告诉我们,kernel设备和systemd进程正在记录大量日志。 事实上,与列出的其他项相比,我们可以看到这两个项比其他项拥有更多的日志消息。

然而,systemdkernel/var/log/messages中有更多的日志消息可能并不罕见。 如果有另一个进程写了很多日志,我们可以在一行程序的输出中看到这一点。 然而,由于我们的第一次运行没有产生任何有用的结果,我们可以修改一行程序来缩小输出范围:

Jun 26 19:51:10 localhost auditd[550]: Started dispatcher: /sbin/audispd pid: 562

如果我们查看一个messages日志条目的格式,我们可以看到在处理之后,可以找到日志消息。 为了进一步缩小搜索范围,我们可以在输出中添加一点消息。

我们可以通过将cut命令的字段列表更改为“1,2,5-8”来实现这一点。 通过在5之后添加“-8”,我们发现cut命令显示从 5 到 8 的所有字段。 这样做的效果是在一行代码中包含每个日志消息的前三个单词:

# grep "Jun 26" /var/log/messages | cut -d\  -f1,2,5-8 | sort | uniq -c | sort -n | tail -30
 64 Jun 26 kernel: 131055 pages RAM
 64 Jun 26 kernel: 5572 pages reserved
 64 Jun 26 kernel: lowmem_reserve[]: 0 462
 77 Jun 26 kernel: [  579]
 79 Jun 26 kernel: Out of memory:
 80 Jun 26 kernel: [<ffffffff810b68f8>] ? ktime_get_ts+0x48/0xe0
 80 Jun 26 kernel: [<ffffffff81102e03>] ? proc_do_uts_string+0xe3/0x130
 80 Jun 26 kernel: [<ffffffff8114520e>] oom_kill_process+0x24e/0x3b0
 80 Jun 26 kernel: [<ffffffff81145a36>] out_of_memory+0x4b6/0x4f0
 80 Jun 26 kernel: [<ffffffff8114b579>] __alloc_pages_nodemask+0xa09/0xb10
 80 Jun 26 kernel: [<ffffffff815dd02d>] dump_header+0x8e/0x214
 80 Jun 26 kernel: [ pid ]
 81 Jun 26 kernel: [<ffffffff8118bc3a>] alloc_pages_vma+0x9a/0x140
 93 Jun 26 kernel: Call Trace:
 93 Jun 26 kernel: [<ffffffff815e19ba>] dump_stack+0x19/0x1b
 93 Jun 26 kernel: [<ffffffff815e97c8>] page_fault+0x28/0x30
 93 Jun 26 kernel: [<ffffffff815ed186>] __do_page_fault+0x156/0x540
 93 Jun 26 kernel: [<ffffffff815ed58a>] do_page_fault+0x1a/0x70
 93 Jun 26 kernel: Free swap 
 93 Jun 26 kernel: Hardware name: innotek
 93 Jun 26 kernel: lowmem_reserve[]: 0 0
 93 Jun 26 kernel: Mem-Info:
 93 Jun 26 kernel: Node 0 DMA:
 93 Jun 26 kernel: Node 0 DMA32:
 93 Jun 26 kernel: Node 0 hugepages_total=0
 93 Jun 26 kernel: Swap cache stats:
 93 Jun 26 kernel: Total swap =
 186 Jun 26 kernel: Node 0 DMA
 186 Jun 26 kernel: Node 0 DMA32
 489 Jun 26 kernel: CPU 

如果我们增加tail命令来显示最后 30 行,我们可以看到一些有趣的趋势。 第一行非常有趣的是输出中的第四行:

 79 Jun 26 kernel: Out of memory:

看起来,kernel打印了以术语“Out of memory”开头的79日志消息。 虽然这看起来似乎有点显而易见,但似乎该服务器可能在某个时刻耗尽了内存。

下面两行有趣的文字似乎也支持这个理论:

 80 Jun 26 kernel: [<ffffffff8114520e>] oom_kill_process+0x24e/0x3b0
 80 Jun 26 kernel: [<ffffffff81145a36>] out_of_memory+0x4b6/0x4f0

第一行似乎表明内核杀死了一个进程; 第二行再次表明存在内存不足的情况。 这个系统是否已经耗尽了内存,并在此过程中杀死了 Apache 进程? 这似乎很有可能。

当 Linux 系统耗尽内存时会发生什么?

在 Linux 上,对内存的管理与其他操作系统略有不同。 当系统内存不足时,内核有一个旨在回收使用的内存的进程; 这个进程称为内存耗尽杀手(oom-kill)。

oom-kill进程被设计用来杀死占用大量内存的进程,以便为关键系统进程释放这些内存。 我们将稍微介绍一下oom-kill,但是首先,我们应该理解 Linux 如何定义内存不足。

最小可用内存

在 Linux 上,当空闲内存低于定义的最小内存时,将启动 oom-kill 进程。 这个最小值当然是一个名为vm.min_free_kbytes的内核可调参数。 此参数允许您设置系统确保始终可用的内存量(以千字节为单位)。

当可用内存低于这个参数的值时,系统开始采取行动。 在深入讨论之前,让我们先看看这个值在我们的系统上设置了什么,并刷新 Linux 中内存的管理方式。

我们可以使用与前一章相同的sysctl命令来查看当前的vm.min_free_kbytes值:

# sysctl vm.min_free_kbytes
vm.min_free_kbytes = 11424

目前,该值为11424千字节或约 11 兆字节。 这意味着我们的系统的空闲内存必须总是大于 11 兆字节,否则系统将启动 oom-kill 进程。 这看起来很简单,但是我们从第 4 章故障诊断性能问题中知道,Linux 管理内存的方式不一定那么简单:

# free
 total       used       free     shared    buffers cached
Mem:        243788     230012      13776         60          0 2272
-/+ buffers/cache:     227740      16048
Swap:      1081340     231908     849432

如果我们在这个系统上运行free命令,我们可以看到当前的内存使用情况以及可用的内存数量。 在深入讨论之前,我们将分解这个输出,以刷新对 Linux 如何使用内存的理解。

 total       used       free     shared    buffers  cached
Mem:        243788     230012      13776         60          0 2272

在第一行中,我们可以看到系统总共有 243MB 的物理内存。 我们可以在第二列中看到目前使用了 230MB,第三列显示未使用的 13MB。 系统正在测量这个未使用的值,以确定当前所需的最小内存是否可用。

这一点很重要,因为如果我们还记得第 4 章性能问题故障排除,我们使用第二个“内存空闲”值来确定有多少内存可用。

 total       used       free     shared    buffers cached
Mem:        243788     230012      13776         60          0 2272
-/+ buffers/cache:     227740      16048

free的第二行中,我们可以看到当系统计算缓存使用的内存时使用的和空闲的内存数量。 如前所述,Linux 系统非常积极地缓存文件和文件系统属性。 所有这些缓存都存储在内存中,我们可以看到,在运行这个free命令的瞬间,缓存使用了 2,272 KB 的内存。

当空闲内存(不包括缓存)开始接近min_free_kbytes值时,系统将开始回收一些用于缓存的内存。 这是为了允许系统缓存它所能缓存的,但在内存较低的情况下,这个缓存将成为一次性的,以防止 oom-kill 进程启动:

Swap:      1081340     231908     849432

free命令的第三行将我们带到 Linux 内存管理的另一个重要步骤:交换。 从前面的行可以看到,当执行这个free命令时,系统从物理内存交换了大约 231MB 的数据到交换设备。

这是我们期望在可用内存不足的系统上看到的情况。 当free内存开始变得稀缺时,系统将开始获取物理内存中的内存对象,并将它们推到交换内存中。

系统开始执行这些交换活动的积极程度很大程度上取决于内核参数vm.swappiness中定义的值:

$ sysctl vm.swappiness
vm.swappiness = 30

在我们的系统中,swappiness值目前被设置为30。 这个可调参数接受 0 到 100 之间的值,其中 100 允许最激进的交换策略。

swappiness值较低时,系统倾向于在将内存对象移动到交换设备之前尽可能长时间地保留物理内存中的内存对象。

快速回顾一下

在讨论 oom-kill 之前,让我们回顾一下在 Linux 系统中内存开始减少时会发生什么。 系统将首先尝试释放用于磁盘缓存的内存对象,并将使用的内存移动到交换设备。 如果系统无法通过前面提到的两个进程释放足够数量的内存,内核将启动“清除内存”进程。

oom-kill 是如何工作的

如前所述,oom-kill 进程是在空闲内存不足时启动的进程。 这个进程被设计用来识别占用大量内存并且对系统操作不重要的进程。

那么,oom-kill 是如何决定的呢? 它实际上是由内核决定的,而且是不断更新的。

在前面的章节中,我们讨论了系统中每个正在运行的进程如何在/proc文件系统中拥有一个文件夹。 kernel维护这个文件夹,其中有许多有趣的文件。

# ls -la /proc/6689/oom_*
-rw-r--r--. 1 root root 0 Jun 29 15:23 /proc/6689/oom_adj
-r--r--r--. 1 root root 0 Jun 29 15:23 /proc/6689/oom_score
-rw-r--r--. 1 root root 0 Jun 29 15:23 /proc/6689/oom_score_adj

前面提到的三个文件特别与 oom-kill 进程以及每个进程被杀死的可能性相关。 我们要看的第一个文件是oom_score文件:

# cat /proc/6689/oom_score
40

如果我们cat这个文件,我们会看到它只包含一个数字。 然而,这个数字对灭呼进程非常重要,因为这个数字是进程 6689 的 OOM 得分。

OOM 评分是kernel分配给进程的一个值,该值确定对应进程的优先级是高还是低。 得分越高,进程被杀死的可能性就越大。 当内核给这个进程赋值时,它会根据进程使用的内存和交换量以及它对系统的临界程度来赋值。

你可能会问自己,我想知道是否有一种方法来调整我的进程的 oom 评分。 这个问题的答案是肯定的,有! 这就是另外两个文件oom_adjoom_score_adj发挥作用的地方。 这两个文件允许您调整进程的 oom 评分,允许您控制进程被杀死的可能性。

目前,oom_adj文件将以折旧方式代替oom_score_adj文件。 因此,我们将只关注oom_score_adj文件。

调整房间评分

oom_score_adj文件支持从-1000 到 1000 的值,其中更高的值将增加 oom-kill 选择进程的可能性。 让我们看看当我们在过程中增加 800 的调整值时,我们的房间评分会发生什么变化:

# echo "800" > /proc/6689/oom_score_adj 
# cat /proc/6689/oom_score
840

只需将内容更改为 800,内核就会检测到此调整,并将 800 添加到该过程的 oom 评分中。 如果这个系统在不久的将来耗尽内存,这个进程绝对会被 oom-kill 杀死。

如果我们将此值更改为-1000,这实际上将从 oom-kill 中排除该进程。

确定我们的进程是否被 oom-kill 杀死

现在,我们已经知道当系统内存不足时,会发生什么,让我们仔细看看系统到底发生了什么。 为此,我们将使用less来读取/var/log/messages文件,并查找“kernel: Out of memory”消息的第一个实例:

Jun 26 00:53:39 blog kernel: Out of memory: Kill process 5664 (processor) score 265 or sacrifice child

有趣的是,“Out of memory”日志消息的第一个实例发生在 Apache 进程被杀死前 20 个小时。 此外,被杀死的进程是一个非常熟悉的进程,即前一章中的“processor”cronjob。

这个单一的日志记录实际上可以告诉我们关于这个进程的很多信息,以及为什么 oom-kill 选择这个进程。 在第一行中,我们可以看到内核给处理器进程的评分为265。 虽然不是最高的分数,但我们已经看到 265 的分数很可能比此时运行的大多数进程的分数都要高。

这似乎表明此时处理器作业占用了相当多的内存。 让我们继续查看这个文件,看看这个系统上可能还发生了什么:

Jun 26 00:54:31 blog kernel: Out of memory: Kill process 5677 (processor) score 273 or sacrifice child

再往下一点,我们可以看到另一个处理器进程被杀死的实例。 似乎每次运行此作业时,系统都会耗尽内存。

为了节省时间,让我们跳到第 21 个小时,仔细看看我们的 Apache 进程被杀死的时间:

Jun 26 21:12:54 localhost kernel: Out of memory: Kill process 2249 (httpd) score 7 or sacrifice child
Jun 26 21:12:54 localhost kernel: Killed process 2249 (httpd) total-vm:462648kB, anon-rss:436kB, file-rss:8kB
Jun 26 21:12:54 localhost kernel: httpd invoked oom-killer: gfp_mask=0x200da, order=0, oom_score_adj=0

看来,messages日志一直都有我们的答案。 在前面的几行中,我们可以看到进程2249,它恰好是我们的 Apache 服务器进程 id:

Jun 26 21:12:55 blog.example.com systemd[1]: httpd.service: main process exited, code=killed, status=9/KILL

这里,我们看到systemd检测到进程在21:12:55被杀死。 此外,我们可以从消息日志中看到,oom-kill 在21:12:54针对这个进程。 在这一点上,毫无疑问这个过程是被 oom-kill 杀死的。

为什么系统内存不足?

此时,我们能够确定 Apache 服务在耗尽内存时被系统杀死。 不幸的是,“毁灭”不是问题的根本原因,而是一种症状。 虽然这是 Apache 服务关闭的原因,但是如果我们仅仅重新启动进程而不做其他事情,那么问题可能会再次发生。

此时,我们需要首先确定是什么导致系统耗尽内存。 要做到这一点,让我们看看消息日志文件中Out of memory消息的整个列表:

# grep "Out of memory" /var/log/messages* | cut -d\  -f1,2,10,12 | uniq -c
 38 /var/log/messages:Jun 28 process (processor)
 1 /var/log/messages:Jun 28 process (application)
 10 /var/log/messages:Jun 28 process (processor)
 1 /var/log/messages-20150615:Jun 10 process (python)
 1 /var/log/messages-20150628:Jun 22 process (processor)
 47 /var/log/messages-20150628:Jun 26 process (processor)
 32 /var/log/messages-20150628:Jun 26 process (httpd)

再次使用cutuniq –c命令,我们可以在消息日志中看到一个有趣的趋势。 我们可以看到内核已经多次调用了 oom-kill。 我们可以看到,即使在今天,系统也启动了“毁灭”进程。

我们现在要做的第一件事就是计算出这个系统有多少内存。

# free -m
 total       used       free     shared    buffers cached
Mem:           238        206         32          0          0 2
-/+ buffers/cache:        203         34
Swap:         1055        428        627

使用free命令,我们可以看到系统有238MB 的物理内存和1055MB 的交换空间。 然而,我们还可以看到只有34MB 的内存是空闲的,并且系统已经交换了428MB 的物理内存。

很明显,对于系统当前所处的工作负载,它没有分配足够的内存。

如果我们回顾一下 oom-kill 的目标过程,我们可以看到一个有趣的趋势:

# grep "Out of memory" /var/log/messages* | cut -d\  -f10,12 | sort | uniq -c
 1 process (application)
 32 process (httpd)
 118 process (processor)
 1 process (python)

这里,很明显的两个最常被杀死的进程是httpdprocessor。 我们在前面学到的是,oom-kill 根据进程使用的内存数量来确定要杀死哪些进程。 这意味着这两个进程在系统上使用了最多的内存,但是它们到底使用了多少内存呢?

# ps -eo rss,size,cmd | grep processor
 0   340 /bin/sh -c /opt/myapp/bin/processor --debug --config /opt/myapp/conf/config.yml > /dev/null
130924 240520 /opt/myapp/bin/processor --debug --config /opt/myapp/conf/config.yml
 964   336 grep --color=auto processor

使用ps命令专门显示rss字段大小,我们在第四章【显示】,故障诊断性能问题,我们可以看到,使用130``processor的工作是 MB 的常驻内存和虚拟内存240MB。

***如果系统只有238MB 的物理内存,而进程正在使用240MB 的虚拟内存,最终,系统将在物理内存不足的情况下运行。

解决长期和短期问题

这一章中讨论的问题可能有点棘手,因为它们通常有两种解决方法。 有一个长期修复方案和一个短期修复方案; 两者都是必要的,但有一个只是暂时的。

长期决心

对于这个问题的长期解决,我们确实有两个选择。 我们可以增加服务器的物理内存,为 Apache 和 Processor 提供足够的内存来完成它们的任务。 或者,我们可以将处理器移动到另一个服务器上。

因为我们知道这个服务器经常杀死 Apache 服务和processor作业,所以很可能是系统上的内存太少,无法同时执行这两个角色。 通过将processor作业(很可能是它所在的自定义应用)移动到另一个系统,我们将把工作负载移动到专用服务器上。

根据处理器的内存使用情况,增加新服务器上的内存也是值得的。 看起来,processor作业使用了足够多的内存,在低内存服务器(比如它现在所在的服务器)上导致内存不足的情况。

坦率地说,决定哪种长期解决方案是最好的取决于导致系统耗尽内存的环境和应用。 在某些情况下,简单地增加服务器的内存并结束工作可能会更好。

这个任务在虚拟和云环境中非常容易,但它可能并不总是最好的答案。 真正决定哪种答案更好取决于你所工作的环境。

短期决议

让我们假设两个长期决议都需要几天的时间来实现。 到目前为止,我们系统上的 Apache 服务仍然处于关闭状态。 这意味着我们公司的博客也仍然处于宕机状态; 为了暂时解决这个问题,我们需要重新启用 Apache。

然而,我们不应该简单地用systemctl命令重启 Apache。 在启动任何操作之前,我们实际上应该首先重启服务器。

当大多数 Linux 管理员听到“让我们重新启动”这句话时,他们的胃里会有一种下沉的感觉。 这是因为,作为 Linux 系统管理员,我们很少需要重新启动系统。 我们被告知,在不更新内核的情况下重启 Linux 服务器是一件很不明智的事情。

在大多数情况下,我们认为重新启动服务器不是正确的解决方案是正确的。 但是,我认为系统耗尽内存是一种特殊情况。

我的观点是,当 oom-kill 启动时,问题系统应该在完全恢复到正常状态之前重新启动。

我这样说的原因是,oom-kill 进程可以杀死任何进程,包括关键的系统进程。 虽然 oom-kill 进程通过 syslog 记录哪些进程被杀死了,但 syslog 守护进程只是系统上另一个可以被 oom-kill 杀死的进程。

在 oom-kill 杀死了许多不同进程的情况下,即使 oom-kill 没有杀死 syslog 进程,也很难确保每个进程都按照应该的方式启动和运行。 当处理这个问题的人缺乏经验时尤其如此。

虽然您可以花时间确定正在运行的进程并确保重新启动每个进程,但简单地重新启动服务器要快得多,而且可以说更安全。 正如您所知道的,在引导时,将启动定义为启动的每个进程。

虽然不是每个系统管理员都同意这个观点,但我认为这是确保系统处于稳定状态的最佳方法。 重要的是要记住,这只是一个短期的解决方案,在重新启动时,除非有什么变化,否则系统可能会再次耗尽内存。

对于我们的情况,最好禁用processor作业,直到服务器的内存可以增加或作业可以移动到专用系统。 然而,这并不是在所有情况下都可以接受的。 就像长期解决方案一样,防止这种情况再次发生也取决于你所管理的环境。

由于我们假设短期解决方案是我们示例中的正确解决方案,我们将继续重新启动系统:

# reboot
Connection to 127.0.0.1 closed by remote host.

一旦系统重新上线,我们就可以用systemctl命令验证 Apache 是否正在运行:

# systemctl status httpd
httpd.service - The Apache HTTP Server
 Loaded: loaded (/usr/lib/systemd/system/httpd.service; enabled)
 Active: active (running) since Wed 2015-07-01 15:37:22 UTC; 1min 29s ago
 Main PID: 1012 (httpd)
 Status: "Total requests: 0; Current requests/sec: 0; Current traffic:   0 B/sec"
 CGroup: /system.slice/httpd.service
 ├─1012 /usr/sbin/httpd -DFOREGROUND
 ├─1439 /usr/sbin/httpd -DFOREGROUND
 ├─1443 /usr/sbin/httpd -DFOREGROUND
 ├─1444 /usr/sbin/httpd -DFOREGROUND
 ├─1445 /usr/sbin/httpd -DFOREGROUND
 └─1449 /usr/sbin/httpd -DFOREGROUND

Jul 01 15:37:22 blog.example.com systemd[1]: Started The Apache HTTP Server.

如果我们在这个系统上再次运行free,我们可以看到的内存利用率要低得多,至少到目前为止是这样的:

# free -m
 total       used       free     shared    buffers cached
Mem:           238        202         35          4          0 86
-/+ buffers/cache:        115        122
Swap:         1055          0       1055

总结

在本章中,我们使用故障排除技能来识别影响公司博客的问题和问题的根本原因。 我们能够使用前面章节中学到的技能和技术来确定 Apache 服务停止了。 我们还确定了这个问题的根本原因是系统耗尽了内存。

通过研究日志文件,我们可以看到系统上使用最多内存的两个进程是 Apache 和一个名为processor的自定义应用。 此外,通过确定这些过程,我们能够提出一个长期的建议,以防止该问题再次发生。

最重要的是,我们了解了 Linux 系统内存耗尽时会发生什么。

在下一章中,我们将通过对无响应系统进行根本原因分析,来测试您到目前为止学到的所有知识。***