
2020年2月份加入去哪儿旅行酒店报价中心研发团队,云原生SIG成员,主要负责国内酒店报价实时和离线计算模块的研发和维护。喜欢钻研云原生相关开发,完成JVM参数校验功能,解决容器应用的OOM被kill等问题。自从公司 2021 年 11 月份开始全面容器化后,酒店报价中心团队快速响应,迁移了 98% 的应用,由原来的 kvm 或实体机器到容器上,我们的多个应用出现了频繁被 kill 的情况,主要包括两大类:应用 GC 时间长导致 k8s 检活失败,k8s 会 kill 掉业务应用。' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
当时我们团队的两个应用在发布到 docker上以后,出现了频繁重启的现象,发布后一天内重启次数高达 29 次左右,提示也仅仅是 “时间:2021-11-25T21:34:58+08:00 原因:Error kill” 看不到具体的问题,只能到对应的容器内部去寻找线索了。具体排查过程如下:' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
首先通过 dmesg 命令,查看容器所在主机上的日志。发现是存在 OOM kill 掉的 Java 应用,但是对比了下这个 total-vm 和我们自己的应用配置发现差别很大,不是我们的应用进程,我们的配置是:' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
舍弃了这个方向后转向了 k8s 的日志(ps:为啥第一次不看这个,是因为这个日志的查看时需要权限的,前期没有权限,只能自己动手先看方便的),发现了在被 kill 之前出现了3次 unhealthy 的 k8s 日志,且返回请求状态不是200。' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
看下为什么会有检活请求异常,检查业务访问日志,发现这个时间点是有接收到请求,手动访问也是成功的。但是当时为啥会有访问状态不是 200 的问题呢?怀疑当时业务进程是有大量任务在跑,响应超时问题导致, 所以开始排查业务的具体日志。在排查日志的时候发现了导致该问题的根本原因,本质是 GC 时间过长导致。查看重启前的容器 GC 日志:' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
容器被重启是在 2021-11-25T21:34:58+08:00 重启的。在这个时间点前,也就是被 kill 之前的一次 GC 时间高达 18s + 7s 。至此,原因就很清晰了:因为应用进程的 GC 导致服务不能正常响应 k8s 的检活请求,k8s 认为应用“死”了,触发了 kill 和重启操作!- 通过 GC 日志,分析主要耗时点。推荐 GC 分析工具:https://gceasy.io/,调整 JVM参数。
- k8s 调整了检活机制,由原来超时 10s、20s,最后调整为 2min。
- 通过分析日志发现主要的长时 GC 是因为新生代晋升失败,扩大 young 区和堆大小优化 JVM 参数。
问题现象是应用管理平台上出现了容器 “OOM kill” 的提示。' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
基于 OOM kill 的提示,开始分析应用日志,发现堆区、栈区并没有出现 OOM 的问题,怀疑是堆外内存内存溢出导致,因此,尝试添加相应的JVM参数以观察堆外内存的使用情况。' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
观察是否是有堆外内存没有释放,再加上 OOM 没有明显征兆,写了脚本定时 30s 看下使用情况。' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
下图是在容器启动后的 1 分钟 到 容器即将被 kill 时的 JVM 内存分配对比图:' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
发现 JVM 的使用内存并没有明显变化(12491M→ 12705M),且整体没有超过 docker 分配的内存限制(docker limit Memory:12G),但是为什么会有 OOM 呢?哪块的内存使用升高导致了 OOM 呢?使用 pmap 分析 Java 进程的内存映射关系:' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
pmap说明
Address: 内存开始地址
Kbytes: 占用内存的字节数(KB)
RSS: 保留内存的字节数(KB)
Dirty: 脏页的字节数(包括共享和私有的)(KB)
Mode: 内存的权限:read、write、execute、shared、private (写时复制)
Mapping: 占用内存的文件、或[anon](分配的内存)、或[stack](堆栈)
Offset: 文件偏移
Device: 设备名 (major:minor)
发现可疑的地方有两个 1029712KB(1005M)的内存块和较多64M内存块,linux 默认使用的 glibc 的 ptmalloc 内存分配器,有这个问题。在进程申请内存时,根据需要分配的内存大小由内存分配器来想内核申请具体的内存区域,那么为什么会有内存分配器来申请内存,而不是进程直接向系统申请呢?因为系统调用的开销比较大,这样做是非常不值的。同时,在 linux下分配堆内存需要使用 brk系统调用,而这个系统调用只是简单地改变堆顶指针而已,也就是将堆扩大或者缩小。举个例子,进程分别申请了 M2 和 M1 两块内存,运行了一段时间后,M2 内存不需要了,需要回收了。' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
使用系统处理的话,只能使用 brk 移动指针,那么 M1 也会被回收掉,这样显然是不行的。所以引入内存分配器,把 M2 的内存缓存下来,等到进程需要再次申请内存空间时不需要使用系统调用,而是直接从缓存中分配,这个动作就是由内存分配器完成的。内存分配器不仅提升了运行效率,还提高了内存的使用率。' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
glibc 的内存分配器(ptmalloc)的结构如图所示,一个进程就有一个主分配区和若干个从分配区。所有的线程申请内存时,都要经过主分配区申请,多线程时就需要通过锁机制来保证分配的正确性,从分区就应运而生了,ptmalloc 根据系统对分配区的争用情况动态增加分配区的数量。' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
在申请内存时,glibc 每次申请新的内存时,主分配区是可以通过 brk 或者 mmap 来向系统申请的,但是非主分配的内存只能通过 mmap 申请了,在64位机器上每次申请的虚拟内存区块大小是 64MB ,最大为8倍的 CPU 数量。且从分配区一旦创建,就不会被回收了。这个就是该问题中发现的 64MB 内存块产生的原因。1. 通过 fastbins 查找合适内存块,
2. 1没有,从 small bin 中获取,
3. 2没有,从 unsorted bin 中获取,
4. 3没有,从 large bin 中获取,
5. 4没有,从 top chunk 中,
1. 判断是否是 mmap 映射,是直接回收
2. 判断是否邻近 top chunk
3. 不是2,根据 size 放到不同的 bins 中
4. 是2,判断 top chunk 中邻近内存是否在使用 是 合并 top chunk
5. 合并后判断 top chunk 大小,超过阈值(默认128k),但是开始分配128k不会回收。通过翻阅资料发现,现在市面上有不少内存分配器的实现,如 tcmalloc ,jemalloc 等,在这里我们选择了 jemalloc。jemalloc 是一个通用的 malloc(3) 实现,强调碎片避免和可扩展的并发支持。' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
在灰度环境尝试替换为 jemalloc 的内存管理器:' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
发现 '64MB' 的空间映射已经不存在了,且在观察时间范围内还有一次内存的下降, 观察一周一直平稳运行,没有出现 OOM kill 的问题。' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
发现问题,就是个人前进的一大步。要发现问题,就要抓细节,不放弃再加上有头脑的处理问题!' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)
华庭 :《Glibc内存管理-Ptmalloc2 源代码分析》
JeMalloc-UncP 知乎
https://jemalloc.net/