一次JVM内存使用率问题的排查

6,937

近几周,组内经常收到一些服务集群的内存监控报警,上周leader决定进行一次问题排查,这个任务正好到了我手上,之前这方面的经验很少,借着这个机会,把书本上的“知识”结合实践,提炼成一篇文章。

问题描述

  • 每次发版后,集群服务内存使用率低于50%,跑着跑着就会飙到94%以上
  • 服务部分线上出现Java进程会挂掉,pod重启现象。

排查过程

根据上面出现的现象我暂定了一下排查过程

  • 查看K8S集群监控的内存情况
  • 查看该服务pod的资源分配情况
  • 查看Pod内Java服务进程的启动JVM参数
  • 查看内存回收情况,观察是否出现明显异常
  • 使用jmap导出dump文件进行分析
  • 根据dump文件分析出的原因进行确定问题代码位置
  • 优化后正确的内存使用率趋势

1. 查看K8S集群监控的内存情况

这是一个问题服务的K8S集群监控内存走势图。从图中我们可以看出,内存即使有小的波动,但使用率一直在上升趋势。

2.查看K8S对该pod的资源分配情况

# 执行命令查看该pod的资源分配情况
kubectl --kubeconfig ${source_config} -n ${namespace} describe pod ${pod_name}

请求内存大小和限制都是8G内存

3.查看Pod内Java服务进程的启动JVM参数

如果是SpringBoot项目内嵌Web容器可以先进入到pod内,然后使用使用下面两个参数查看JVM参数。

# 查看已经启动的java服务参数
ps -ef | grep java
# 使用jinfo查看
jinfo -flags ${pid}

我这的服务都是-Xms5769m -Xmx5769m -Xmn2884m 其他参数省略,到这就有问题点出现了,我们的内存监控图显示,当前使用在7.13GB,可是我们JVM设置堆的内存远小于这个值。

4.查看内存回收情况,观察是否出现明显异常

该容器总体内存使用情况正常,波动代表着回收前后内存。

你也可以使用其他jvm命令在pod内查看某一刻的内存情况,或者可以直接看gc的log,进行整体分析

# 每refresh_time毫秒打印一次内存使用情况gc次数等
jstat -gc ${pid} ${refresh_time}
# 你查看时刻的内存使用情况
jmap -heap ${pid}

我们的jvm内存是正常的值,说明有堆外的内存被占用,使用top查看下 这里有个坑,used的总值是集群pod的值,并不是该pod的,当时排查这个点的时候差点以为Prometheus的探针有问题,质疑Grafana呈现的监控数据准确性。仔细观察后,发现RES值与内存监控图该时刻内存的7.13G是近似的,说明探针没问题。分析到这的时候,我得出结论,该服务堆内内存情况正常,可能是堆外内存使用有问题?带着这个疑问继续排查。

5.使用jmap导出dump文件进行分析

先生成该时刻的dump文件

jmap -dump:live,format=b,file=${dump_name}.bin ${PID}

下载MAT,打开进行dump文件分析,选择Leak Suspects

可以看到539个线程对象,为何该服务会创建这么多呢?

打开thread_overview XNIO-2前缀这个线程池,成功引起了我的注意,我过滤下后发现这个线程创建了320个,一直阻塞的存活着。 I/O-dispatch前缀这个线程池,也成功引起了我的注意,我过滤下后发现这个线程创建了120个,一直阻塞的存活着。

6.根据dump文件分析出的原因进行确定问题代码位置

XNIO-2线程池,好熟悉的名字,它好像在对我唱:我们好像在哪见过,你记得吗?emmmm,我真想不起来,但我知道你肯定不是我定义的线程池,因为我都会指定名字。那就grep服务日志,我发现undertow容器在启动的时候会打印。

打开undertow容器的源码:

ioThreads = 默认值得逻辑核数
workerThreads = ioThreads * 8

我们上面看k8s指定该pod的cpu为1C,按照上面320个线程,那应该是40C。带着这个疑问登录pod,使用lscpu查看下CPU的逻辑核数。

发现逻辑核数确实是40C,问了CD组,他们说这块确实有的pod启动时候,会出现这种情况,读取的pod逻辑核数为这个服务整体资源池的逻辑核。看了下服务的配置文件,是没有指定undertow的线程大小的,所以配置下:

server.undertow.io-threads= io线程数
server.undertow.worker-threads= 工作线程数

epollWait的调用栈,一看就是nio相关,思考了下服务内部,除了undertow之外,只有rpc会使用,看了下rpc的配置,worker默认指定了120,这显然是不合理,将其降为16。

7.优化后正确的内存使用率趋势

上线后重启,观察了几天,整体服务内存使用情况已经趋于正常。

整体趋势为恒小于JVM配置的5.7G的内存,而且整体没有再出现1那种那种趋于递增的情况。

总结:

  • 本文介绍了只是一种比较特殊的情况,获取pod核数不正常的情况,导致一直在申请堆外内存。
  • 对于NIO这块为什么会park的等待新消费,可以看下我之前的NIO线程模型文章(《深入的聊聊NIO》)。
  • JVM问题排查的思路,我觉得大体上都是这个过程,只不过在有可能在某一步就提前确定了问题,比如频繁GC,或者老年代对象过多等等问题可能在分析GC的log时候就已经确认了,但是具体定位代码一定是从dump文件分析出来的。
  • 这次调整后,整体内存资源使用情况降了接近40%的内存,为我们部门省了很多资源。

相关链接