某次压测时物理内存被用光 Tomcat 被 Kernel kill 掉的案例

2153人阅读 评论(0) 收藏 举报
分类:

背景描述

某项目结构图如下(前端交互式体验及对象存储为主,redis 及 rds 负载较小没有画出):

aem-architecture.png

web1 和 web2 是两个 Apache,publisher1 和 publisher2 是两个 Tomcat 容器下的 app 应用服务器。

在对该项目进行压测时,并发数加到 750 左右,阿里云 PTS 压测工具监测到在某个时间点后 tps 呈下降趋势:

pts-实时监控-业务指标-tps.png
作为对应指标的响应时间(rt)在这个时间点呈上升趋势:
pts-实时监控-业务指标-响应时间.png

查看实时监控-监控集指标,发现 publisher1 节点的 CPU 利用率已降为 1.9,在高并发的时候这个值肯定是有问题,很可能这个节点已经宕掉:

pts-实时监控-监控集指标-CPU.png

查看网络流量发现该节点果然已经没有了网络流量:

pts-实时监控-监控集指标-网络.png
ssh 登录 publisher1 ps 证实 Tomcat 确实已经 crash。但查 Tomcat 日志、应用日志,没有任何异常,find 也没找到类似于 hs_err_pidNNN.log 之类的 crash 日志。Tomcat 内存分配情况:
JAVA_OPTS="-Xmx3072m"

系统物理内存 8G,看上去绰绰有余。真的是这样吗?

原因分析

一般来讲,诸如内存溢出之类常见的 Tomcat 崩溃都会在容器日志或者 crash 日志中记录原因。但不排除这种情况:Linux 允许系统中的进程申请比现有系统可用内存还要多的内存,但当整个系统内存不足的时候,Kernel 会将耗用内存最多的那个进程给干掉,就是 Tomcat 了,但这并不能说明 Tomcat 发生了某些运行时的致命错误,所以我们没有看到任何容器、应用甚至 jvm 级别的异常,Tomcat 来不及做任何日志处理就 Over 了。
查看 /var/log/messages,在 PTS 指示的时间点找到了以下日志:
Jul 25 03:15:39 localhost kernel: [91918.878735] httpd invoked oom-killer: gfp_mask=0x24200ca(GFP_HIGHUSER_MOVABLE), nodemask=0, order=0, oom_score_adj=0

...

Jul 25 03:15:39 localhost kernel: [91919.032621] 0 pages in swap cache
Jul 25 03:15:39 localhost kernel: [91919.033999] Swap cache stats: add 0, delete 0, find 0/0
Jul 25 03:15:39 localhost kernel: [91919.036137] Free swap  = 0kB
Jul 25 03:15:39 localhost kernel: [91919.037343] Total swap = 0kB
Jul 25 03:15:39 localhost kernel: [91919.038605] 2097053 pages RAM
Jul 25 03:15:39 localhost kernel: [91919.039849] 0 pages HighMem/MovableOnly

...

Jul 25 03:15:39 localhost kernel: [91919.042738] [ pid ]   uid  tgid total_vm      rss nr_ptes nr_pmds swapents oom_score_adj name
Jul 25 03:15:39 localhost kernel: [91919.046327] [ 1623]     0  1623     2828      201      11       3        0         -1000 udevd
Jul 25 03:15:39 localhost kernel: [91919.231201] [  486]     0   486 12933081   879709    4090      53        0             0 java
Jul 25 03:15:39 localhost kernel: [91919.273553] [ 7903]     0  7903     1079       24       7       3        0             0 cronolog
...
Jul 25 03:15:39 localhost kernel: [91921.135391] Out of memory: Kill process 486 (java) score 419 or sacrifice child
Jul 25 03:15:39 localhost kernel: [91921.138827] Killed process 486 (java) total-vm:51732324kB, anon-rss:3518836kB, file-rss:0kB, shmem-rss:0kB

注意以上系统时间为 UTC 时间,对应北京时间为 Jul 25 11:15:39,PTS 监控到的 publisher1 节点的内存曲线图的顶点跟 OOM 的时间也基本一致:
pts-实时监控-监控集指标-内存.png

可以看到在 11:15 左右 publisher1 节点的 8G 物理内存已经用光。

解决方案

当 Linux 系统物理内存不够用的时候,需要将物理内存中的一部分空间释放出来以供当前运行程序使用。这些被释放出来的空间很可能来自于一些长时间没有什么操作的程序,这些被释放出来的空间会被临时存放到 SWAP 空间,等这些程序要运行时,再从 SWAP 恢复数据到内存。上述案例 publisher1 节点 SWAP 查看:
$ free -m
             total       used       free     shared    buffers     cached
Mem:          7985       4158       3826         10         13        219
-/+ buffers/cache:       3925       4059

Swap:            0          0          0

$ cat /proc/swaps
Filename                                Type            Size    Used    Priority

交换分区空间没有,系统在物理内存不够的时候也就没有临时空间可以利用,为了整个系统的正常运行,"oom_killer" 函数被调用了,于是 Tomcat 悲剧了。。。

解决方案似乎已经很明显了(参考博客《Linux 如何添加一个 Swap 文件》)。值得一提的是,在上面的 message 日志里,Kernel 在筛选要干掉的进程的日志里,在其前面紧挨着的便是指示 SWAP 为 0 无交换空间可用:)

参考资料

Tomcat stopped without any log or any stack
Out of Memory + httpd.worker invoked oom-killer

博主 20170727 日续:关于 Apache 的类似案例

上述案例中 app 节点,也就是 publisher1 节点修复以后,继续加压测试,在并发数达到 1000 的时候,web2 节点宕掉。具体表象为 web2 服务器 SSH 连不上,阿里云 PTS 监控集也显示为 web2 处于下线状态。

查看 web2 的 /var/log/messages,该时间段日志摘要如下:

Jul 26 08:16:01 CN-LAMP-STG-M-0005-UFS-V3-WEB-02 kernel: [  554.469621] httpd invoked oom-killer: gfp_mask=0x24201ca(GFP_HIGHUSER_MOVABLE|__GFP_COLD), nodemask=0, order=0, oom_score_adj=0
Jul 26 08:16:01 CN-LAMP-STG-M-0005-UFS-V3-WEB-02 kernel: [  554.474732] httpd cpuset=/ mems_allowed=0
...
Jul 26 08:16:01 CN-LAMP-STG-M-0005-UFS-V3-WEB-02 kernel: [  554.619479] 0 pages in swap cache
Jul 26 08:16:01 CN-LAMP-STG-M-0005-UFS-V3-WEB-02 kernel: [  554.620912] Swap cache stats: add 0, delete 0, find 0/0
Jul 26 08:16:01 CN-LAMP-STG-M-0005-UFS-V3-WEB-02 kernel: [  554.623248] Free swap  = 0kB
Jul 26 08:16:01 CN-LAMP-STG-M-0005-UFS-V3-WEB-02 kernel: [  554.624566] Total swap = 0kB
...
Jul 26 08:16:01 CN-LAMP-STG-M-0005-UFS-V3-WEB-02 kernel: [  554.630247] [ pid ]   uid  tgid total_vm      rss nr_ptes nr_pmds swapents oom_score_adj name
Jul 26 08:16:01 CN-LAMP-STG-M-0005-UFS-V3-WEB-02 kernel: [  554.633759] [ 1556]     0  1556     2865      218      11       3        0         -1000 udevd
Jul 26 08:16:01 CN-LAMP-STG-M-0005-UFS-V3-WEB-02 kernel: [  554.796157] [ 3306]     0  3306   193666     6316     291       4        0             0 httpd
Jul 26 08:16:01 CN-LAMP-STG-M-0005-UFS-V3-WEB-02 kernel: [  558.310852] [ 9863]    48  9863   195801     3725     275       4        0             0 httpd
...
Jul 26 08:16:01 CN-LAMP-STG-M-0005-UFS-V3-WEB-02 kernel: [  558.512008] Out of memory: Kill process 3306 (httpd) score 12 or sacrifice child
Jul 26 08:16:01 CN-LAMP-STG-M-0005-UFS-V3-WEB-02 kernel: [  558.515331] Killed process 9863 (httpd) total-vm:783204kB, anon-rss:14768kB, file-rss:4kB, shmem-rss:128kB

日志处理逻辑看上去和 publisher1 干掉 Tomcat 的做法一般无二,区别在于 Apache 为了保证高可用性在 httpd worker 进程故障后会再拉起一个,系统物理内存最终被耗光而 OOME 宕机。于是 Publisher1 的表象为 Tomcat 的 crash,而 web2 的表象为 Linux 系统无响应。

解决办法是,除了像 publisher1 那样给 web2 启用虚拟空间,还可以降低 Apache 的最大连接数 MaxClients、最大内存 ServerLimit,修改后使用命令 service httpd restart 对 apache 进行重启使配置生效。

2
1

查看评论
* 以上用户言论只代表其个人观点,不代表CSDN网站的观点或立场
    个人资料
    • 访问:4505588次
    • 积分:35893
    • 等级:
    • 排名:第126名
    • 原创:240篇
    • 转载:35篇
    • 译文:160篇
    • 评论:1491条
    个人微博
    文章存档