1、问题背景
深夜,小菜同学突然被一阵急促的报警声吵醒,原来是手机收到了一连串关于容器内存使用率过高的报警信息。赶紧打开电脑查看服务器状态,发现容器内存使用率持续高达99%,下面把排查的过程和分析记录下来,以供大家参考。
2、问题现象
接收到系统的报警后,小菜同学立即检查了容器状态,观察到以下现象:
- JVM堆内存使用率正常,在50%左右波动,在凌晨1点的时候年轻代使用无明显波动,老年代使用有直线上涨,但是执行了一次
Full GC(也可能是Major GC)
后恢复了正常。 - 容器内存使用率在凌晨1点的时候有一个直线的上涨,并且随后一直保持在上涨后的水平。
服务使用的配置如下:
主要启动参数:-Xms4g -Xmx4g -Xmn2g -XX:+UseG1GC -XX:G1HeapRegionSize=8m -XX:G1ReservePercent=15 -XX:InitiatingHeapOccupancyPercent=50
容器配置:4C5G
3、定位原因
虽然容器内存已经使用了99%,但是JVM堆使用率在经过一次Full GC
后已经降到了50%之后,所以并没有立马重启服务,还是先来看看造成Full GC
的原因。
鉴于堆使用率已经恢复正常,查看当时的内存快照意义不大,因此决定首先从观察到的现象入手。因为凌晨1点的时候系统的流量不会很大,所以大概率是因为定时任务造成了,先排查报警服务凌晨1点执行的定时任务。幸运的是调度平台当时只有一个定时任务在执行,立马查看对应的逻辑,发现了以下代码片段中潜在的问题(简化之后):
由于大部分订单包含12至24期账单,导致此处的orderBills在平均情况下含有数千至数万条数据。经过粗略估算,这些对象的总大小大约为5MB左右。
看启动参数中G1HeapRegionSize=8m
,代表每个Region的大小为8M,G1 GC
会将大于Region一半大小的对象直接分配到老年代。所以orderBills对象会被直接分配到老年代,这也和在凌晨1点的时候年轻代使用无明显波动,老年代使用有直线上涨的现象相符合。在后续的循环中,由于垃圾收集器清理的速度赶不上内存分配的速度,导致垃圾逐渐积累并最终填满整个堆空间,触发了Full GC
。
不过小菜同学有点疑惑为什么GC之后容器的内存还是一直居高不下呢?
经过一番查阅资料,原来JVM启动时并不会立即实际占用全部Xms
指定的内存。Xms
参数指定的是堆的初始大小,JVM会按照这个值预留内存空间,但实际上只有在需要时才会逐渐使用这些预留的内存。
JVM在完成内存释放后,是否将释放的内存返回给操作系统,这一行为取决于具体的JVM实现及其采用的垃圾回收策略。在很多情况下,JVM在进行垃圾收集并释放了堆内存之后,并不会立即将这部分内存归还给操作系统。相反,它会保留这部分内存以备将来Java应用程序的使用,因为从操作系统重新申请内存通常会比从JVM内部管理的内存分配更为昂贵(时间成本上)。所以一般程序还会将Xms
和Xmx
配置为相等的大小,避免频繁申请和释放内存造成的性能开销。
上面两个问题找到原因了,小菜同学决定在本地复现一下进行验证。
新建一个memorytest
项目,写一个方法模拟内存分配:
用以下命令启动:
使用Jdk自带的命令查询JVM内存分配情况,先使用jps -l
查询进程ID:
使用jmap -heap <pid>
查询堆内存分配:
使用jstat -gcutil <pid> <interval[s|ms]>
1秒1次监控堆内存使用和GC情况(也可以使用jconsole
可视化处理工具来查看内存的使用情况):
该命令返回的主要的参数的意义:S0
:Survivor space 0
区的使用率。S1
:Survivor space 1
区的使用率。E
:Eden
区的使用率。O
:Old
区(老年代)的使用率。YGC
:年轻代垃圾收集事件的次数。YGCT
:年轻代垃圾收集所耗费的时间(秒)。FGC
:Full GC(全堆垃圾收集)
事件的次数。FGCT
:Full GC
所耗费的时间(秒)。GCT
:垃圾收集所耗费的总时间(秒)。
此时使用ps aux --sort -rss
查看Java进程占用的本机内存才370MB左右,并没有直接占用Xms
设置的2g。
该命令返回的主要的参数的意义:PID
: 进程ID。%CPU
: 进程使用的CPU百分比。%MEM
: 进程使用的物理内存百分比。RSS
: 进程当前占用的物理内存大小,单位通常是KB。COMMAND
: 启动进程的命令行命令。
开始模拟业务分配内存,为了方便观察直接循环100000次,每次分配5MB空间:
jstat此时监控到内存情况:
此时可以看到对象都直接分配到了老年代,年轻代的内存使用没有多大的变化,并且当YGC(Young Generation Garbage Collection,年轻代垃圾回收)
来不及回收时就会发生FGC(Full Garbage Collection,全堆垃圾回收)
。
此时再使用ps aux --sort -rss
查看Java进程占用的本机内存已经到了2G了,并且在方法执行完成后(也包括FGC
后)也没有释放此内存。
再模拟一次业务分配内存,为了方便观察直接循环100000次,这次每次分配2MB空间:
jstat此时监控到内存情况:
此时很明显可以看到对象都直接分配到了年轻代,年轻代的回收效率也比老年代高,并且没有产生FGC
。
再结合本次报警的现象,解决办法也呼之欲出:
- 通过减少查询返回的数据量,避免大对象直接分配至老年代。
- 调整Region大小,较大的Region可以提高大对象分配的效率,同时可能会导致GC停顿时间变长,较小的Region可能意味着更短的停顿时间,但是会增加维护开销,可能导致更高的CPU使用率。所以需要通过监控工具(如
JConsole
、VisualVM
等)观察不同Region大小设置下的GC表现和应用吞吐量,以找到最佳平衡点。
4、问题小结
JVM内存问题可能不常有,但是一旦发生可能对我们系统造成极大的影响,此次内存飙升也给我们敲响了警钟,发现了我们在这边注重的不够,很多监控和日志并不完整,如启动参数中没有加上发生OOM
时自动dump文件的参数等。好在此次服务未受到影响,所有有足够的时候给我们去排查和验证。特此结合此次排查的过程的一些收获记录一下,假设下次还有发生可以有所参考:
- 如果对业务产生了影响,服务不可用或者进程直接没有了,首先需要快速止损,包括熔断、重启、手动GC等方式。但是操作前需要先dump出内存快照方便问题排查,命令如下:
还有在启动参数中添加发生OOM时自动生成heapdump的参数:-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/heap.bin
启动参数中添加GC日志打印相关的参数:
- 如果对业务无影响,可以先观察现象进行排查。如果是近期有业务增加,则可以考虑是否需要扩容,如果是周期性的表现,则可以排查定时任务。
- 对导出的内存快照文件使用MAT等工具进行分析,一般会比较直观的看到当前堆内情况。
- 如果服务还可用,也可以使用命令进行排查,Jdk本身也已经提供非常多轻量的小工具,主要用于监视虚拟机运行状态和进行故障处理,常用的如下(还有一些第三方的工具也很好用,如
arthas
等):
- 如果是栈溢出,抛出
StackOverflowError
异常,需要着重检查是否有死循环或者代码调用链路不合理。 - 还有可能是堆外内存泄露(元空间、直接内存等),此情况一般较少发生,排查起来也更加复杂,小菜同学对于这部分的实操有限,这里就不详细分析了,还需要继续学习。
5、总结
面对内存使用率的异常,我们不仅要关注即时的解决方案,还需要考虑如何从根本上避免此类问题的再次发生。如使用优化数据结构、减少不必要的计算、采用懒加载等策略,以及建立细致的内存监控体系等。性能优化不应该仅仅是面对问题时的临时行动,而应该成为开发文化的一部分。