转载 

​记录一次线上JVM堆外内存泄漏问题的排查过程

分类:    86人阅读    IT小君  2024-05-28 22:39

故障描述

图片
image.png

像是Java进程出现了内存泄漏的情况,但我们的堆内存限制为4G。由于内存占用超过了4G,可以初步判断是JVM堆外内存泄漏。 确认了下当时服务进程的启动配置: -Xms4g -Xmx4g -Xmn2g -Xss1024K -XX:PermSize=256m -XX:MaxPermSize=512m -XX:ParallelGCThreads=20 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+UseCMSCompactAtFullCollection -XX:CMSInitiatingOccupancyFraction=80尽管当天没有上线新代码,但在当天上午,我们正在使用消息队列推送历史数据的修复脚本。该任务会大量调用我们服务中的某一个接口,所以我们初步怀疑与该接口有关。 下图显示了该接口调用量在案发当天的变化情况:

图片
image.png

可以看到,调用量在案发当时相比正常情况下的每分钟200+次大大增加到每分钟5000+次。 我们暂时停止了脚本发送消息,该接口的调用量下降到每分钟200+次,容器内存的上升速度也不再那么快,一切似乎恢复了正常。 接下来,我们需要排查是否这个接口发生了内存泄漏。

排查过程

首先,让我们回顾一下Java进程的内存分配方式,以便更好地阐述我们的排查思路。 以我们线上使用的JDK1.8版本为例,JVM内存分配可以划分为两个区域:堆区和非堆区。

  • • 堆区:包括新生代和老年代。

  • • 非堆区:包括元数据区和直接内存。

图片
image.png

需要特别注意的是,永久代(JDK8中的原生去)存放JVM运行时使用的类,永久代的对象在进行full GC时进行垃圾收集。 经过回顾JVM内存分配的知识,让我们回到故障现场。

堆内存分析

虽然最初我们基本确认与堆内存无关,因为泄露的内存占用超过了堆内存限制4G,但为了保险起见,我们先检查一下堆内存是否有线索。

我们观察了新生代和老年代内存的占用曲线以及垃圾回收次数统计,和往常一样,并没有发现大问题。接下来,我们在事故现场的容器上生成了一份JVM堆内存的日志。

堆内存Dump

堆内存快照dump命令: jmap -dump:live,format=b,file=xxxx.hprof pid

你也可以使用jmap -histo:live pid直接查看堆内存存活的对象。

导出后,将Dump文件下载回本地,然后可以使用Eclipse的MAT(Memory Analyzer)或者JDK自带的JVisualVM打开日志文件。 使用MAT打开文件如图所示:

图片
image.png

在堆内存中,可以看到一些与nio相关的大对象,比如正在接收消息队列消息的nioChannel,还有nio.HeapByteBuffer,但是数量并不多,不能作为判断的依据,先放着观察下。

接下来,我开始浏览该接口代码,接口内部的主要逻辑是调用集团的客户端,将数据库表中的数据查表后写入系统,没有其他额外逻辑。

发现没有什么特殊逻辑后,我开始怀疑客户端封装是否存在内存泄漏。我怀疑的理由是,客户端底层是由其他客户端封装的,作为RPC框架,其底层通讯传输协议有可能会申请直接内存。

我开始考虑是否是我的代码触发了WCS客户端的Bug,导致不断地申请直接内存的调用,最终导致内存被耗尽。

我联系上了值班人员,并将我们遇到的问题和他们进行了描述。他们回复说,会在他们本地执行写入操作的压力测试,看看能否复现我们的问题。

既然等待他们的反馈还需要时间,我们决定先自己思考可能的原因。

我将怀疑的目光停留在直接内存上,怀疑是由于接口调用量过大,客户端对nio的使用不当,导致使用ByteBuffer申请过多的直接内存。

最终结果证明,这个先入为主的思路导致我们在排查过程中走了弯路。在问题的排查过程中,用合理的猜测来缩小排查范围是可以的,但最好先把每种可能性都列清楚。当发现自己深入某个可能性无果时,要及时回头仔细审视其他可能性。

沙箱环境复现

为了还原当时的故障场景,我在测试环境中申请了一台压测机器,以确保和线上环境的一致性。

首先,我们模拟了内存溢出的情况,通过大量调用接口来触发故障。我们使用脚本不断推送数据,持续调用我们的接口,并观察内存的占用情况。

在开始调用接口后,我们注意到内存开始持续增长,并且没有受到限制(没有因为限制触发Full GC)。

图片
image.png

接下来,我们模拟了平时正常调用量的情况。我们将该接口的正常调用量(相对较小,并且每10分钟进行一次批量调用)切换到压测机器上,并得到了以下老生代内存和物理内存的趋势图:

图片
image.png
图片
image.png

问题来了:为什么内存会不断增长并最终耗尽呢?

我们当时猜测是因为JVM进程并没有对直接内存大小进行限制(-XX:MaxDirectMemorySize),所以堆外内存不断增加,而没有触发Full GC操作。

通过上图,我们可以得出两个结论:

在接口调用量很大且发生内存泄漏的情况下,如果老年代堆内存等条件一直不满足Full GC的条件,就不会触发Full GC,直接内存会持续增长。

在平时低调用量的情况下,内存泄漏的速度较慢,总会出现Full GC,回收掉泄漏的部分。这也解释了为什么在平时运行正常的情况下没有出现问题。

由于我们的进程启动参数中没有限制直接内存,于是我们加上了-XX:MaxDirectMemorySize配置,并在沙箱环境进行了再次测试。

结果发现,进程占用的物理内存仍然持续增长,并超出了我们设置的限制。看起来配置似乎没有起作用。

这让我感到很惊讶,难道JVM对内存的限制出现了问题?

到这一步,我们可以看出在排查过程中,我过于执着于直接内存的泄漏问题,而忽视了其他可能性。

我们应该相信JVM对内存的管理能力。如果发现参数失效,应该先从自己的使用方式找原因,看看是不是自己使用参数的方式有误。

直接内存分析

为了更进一步调查直接内存中到底有什么内容,我开始对直接内存进行分析。由于直接内存不像堆内存那样容易查看所有占用的对象,我们需要使用一些命令来进行排查。我尝试了几种方法,以查看直接内存中的问题。

查看进程内存信息 pmap

pmap - report memory map of a process(查看进程的内存映像信息) pmap命令用于报告进程的内存映射关系,是Linux调试及运维一个很好的工具。 pmap -x pid 如果需要排序  | sort -n -k3**

执行后我得到了下面的输出,删减输出如下: .. 00007fa2d4000000    8660    8660    8660 rw---   [ anon ] 00007fa65f12a000    8664    8664    8664 rw---   [ anon ] 00007fa610000000    9840    9832    9832 rw---   [ anon ] 00007fa5f75ff000   10244   10244   10244 rw---   [ anon ] 00007fa6005fe000   59400   10276   10276 rw---   [ anon ] 00007fa3f8000000   10468   10468   10468 rw---   [ anon ] 00007fa60c000000   10480   10480   10480 rw---   [ anon ] 00007fa614000000   10724   10696   10696 rw---   [ anon ] 00007fa6e1c59000   13048   11228       0 r-x-- libjvm.so 00007fa604000000   12140   12016   12016 rw---   [ anon ] 00007fa654000000   13316   13096   13096 rw---   [ anon ] 00007fa618000000   16888   16748   16748 rw---   [ anon ] 00007fa624000000   37504   18756   18756 rw---   [ anon ] 00007fa62c000000   53220   22368   22368 rw---   [ anon ] 00007fa630000000   25128   23648   23648 rw---   [ anon ] 00007fa63c000000   28044   24300   24300 rw---   [ anon ] 00007fa61c000000   42376   27348   27348 rw---   [ anon ] 00007fa628000000   29692   27388   27388 rw---   [ anon ] 00007fa640000000   28016   28016   28016 rw---   [ anon ] 00007fa620000000   28228   28216   28216 rw---   [ anon ] 00007fa634000000   36096   30024   30024 rw---   [ anon ] 00007fa638000000   65516   40128   40128 rw---   [ anon ] 00007fa478000000   46280   46240   46240 rw---   [ anon ] 0000000000f7e000   47980   47856   47856 rw---   [ anon ] 00007fa67ccf0000   52288   51264   51264 rw---   [ anon ] 00007fa6dc000000   65512   63264   63264 rw---   [ anon ] 00007fa6cd000000   71296   68916   68916 rwx--   [ anon ] 00000006c0000000 4359360 2735484 2735484 rw---   [ anon ]

可以看出,最下面一行是堆内存的映射,占用了4G,而其他上面有很多小的内存占用,但通过这些信息我们依然无法看出问题所在。

堆外内存跟踪 NativeMemoryTracking

Native Memory Tracking (NMT) 是Hotspot VM用来分析VM内部内存使用情况的一个功能。我们可以使用jdk自带的jcmd工具来访问NMT的数据。但需要注意的是,打开NMT会带来5%-10%的性能损耗。

-XX:NativeMemoryTracking=[off | summary | detail] # off: 默认关闭 # summary: 只统计各个分类的内存使用情况. # detail: Collect memory usage by individual call sites.

然后运行进程,可以使用下面的命令查看直接内存: jcmd  VM.native_memory [summary | detail | baseline | summary.diff | detail.diff | shutdown] [scale= KB | MB | GB]  

summary: 分类内存使用情况.

detail: 详细内存使用情况,除了summary信息之外还包含了虚拟内存使用情况。

baseline: 创建内存使用快照,方便和后面做对比

summary.diff: 和上一次baseline的summary对比

detail.diff: 和上一次baseline的detail对比

shutdown: 关闭NMT

我们使用: jcmd pid VM.native_memory detail scale=MB > temp.txt

得到如图结果:

图片
image.png
图片
image.png

从上面的信息中,我们无法明显地看出问题所在。至少在当时,我无法通过这些信息找到问题。 排查工作似乎陷入了僵局。

山重水复疑无路

在排查工作陷入停滞时,他们都确认了他们的封装中没有内存泄漏的存在。WCS方面表示没有使用直接内存,而SCF虽然作为底层RPC协议,但并不会留下这么明显的内存泄漏问题,否则应该会有很多反馈。

查看JVM内存信息 jmap

于是,我新开了一个沙箱容器,运行服务进程,并使用jmap命令查看JVM的实际内存配置:

jmap -heap pid

得到结果: Attaching to process ID 1474, please wait... Debugger attached successfully. Server compiler detected. JVM version is 25.66-b17

using parallel threads in the new generation. using thread-local object allocation. Concurrent Mark-Sweep GC

Heap Configuration:    MinHeapFreeRatio         = 40    MaxHeapFreeRatio         = 70    MaxHeapSize              = 4294967296 (4096.0MB)    NewSize                  = 2147483648 (2048.0MB)    MaxNewSize               = 2147483648 (2048.0MB)    OldSize                  = 2147483648 (2048.0MB)    NewRatio                 = 2    SurvivorRatio            = 8    MetaspaceSize            = 21807104 (20.796875MB)    CompressedClassSpaceSize = 1073741824 (1024.0MB)    MaxMetaspaceSize         = 17592186044415 MB    G1HeapRegionSize         = 0 (0.0MB)

Heap Usage: New Generation (Eden + 1 Survivor Space):    capacity = 1932787712 (1843.25MB)    used     = 1698208480 (1619.5378112792969MB)    free     = 234579232 (223.71218872070312MB)    87.86316621615607% used Eden Space:    capacity = 1718091776 (1638.5MB)    used     = 1690833680 (1612.504653930664MB)    free     = 27258096 (25.995346069335938MB)    98.41346682518548% used From Space:    capacity = 214695936 (204.75MB)    used     = 7374800 (7.0331573486328125MB)    free     = 207321136 (197.7168426513672MB)    3.4349974840697497% used To Space:    capacity = 214695936 (204.75MB)    used     = 0 (0.0MB)    free     = 214695936 (204.75MB)    0.0% used concurrent mark-sweep generation:    capacity = 2147483648 (2048.0MB)    used     = 322602776 (307.6579818725586MB)    free     = 1824880872 (1740.3420181274414MB)    15.022362396121025% used

29425 interned Strings occupying 3202824 bytes

输出的信息中,老年代和新生代的占用都看起来很正常,元空间也只占用了20M,而直接内存看起来是2G。 但是,为什么MaxMetaspaceSize = 17592186044415 MB?看起来就像没有设置限制一样。 再仔细看看我们的启动参数: -Xms4g -Xmx4g -Xmn2g -Xss1024K -XX:PermSize=256m -XX:MaxPermSize=512m -XX:ParallelGCThreads=20 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+UseCMSCompactAtFullCollection -XX:CMSInitiatingOccupancyFraction=80

配置的是-XX:PermSize=256m -XX:MaxPermSize=512m,也就是永久代的内存空间。「而1.8后,Hotspot虚拟机已经移除了永久代,使用了元空间代替。」 由于我们线上使用的是JDK1.8,「所以我们对于元空间的最大容量根本就没有做限制」,-XX:PermSize=256m -XX:MaxPermSize=512m 这两个参数对于1.8就是过期的参数。 下面的图描述了从1.7到1.8,永久代的变更:

图片
image.png

为了方便更改参数和使用JVisualVM工具直观地观察内存变化,我选择在本地进行测试。 难道是元空间出现了内存泄漏? 为了方便更改参数和使用JVisualVM工具直观地观察内存变化,我选择在本地进行测试。

使用JVisualVM观察进程运行

首先,我限制了元空间的大小,使用了参数-XX:MetaspaceSize=64m -XX:MaxMetaspaceSize=128m,并在本地循环调用出问题的接口。 得到如图:

图片
image.png

可以观察到,在元空间耗尽时,系统触发了Full GC,并回收了元空间的内存,并卸载了许多类。 然后我们将元空间限制去掉,也就是使用之前出问题的参数: -Xms4g -Xmx4g -Xmn2g -Xss1024K -XX:ParallelGCThreads=20 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+UseCMSCompactAtFullCollection -XX:CMSInitiatingOccupancyFraction=80 -XX:MaxDirectMemorySize=2g -XX:+UnlockDiagnosticVMOptions得到如图:

图片
image.png

进一步观察发现,元空间不断增长,并且已加载的类数量随着调用量的增加而增加,呈现正相关的趋势。

柳暗花明又一村

问题一下子变得明朗起来。随着每次接口的调用,极有可能是某个类不断被创建,占用了元空间的内存。在调试程序时,有时需要查看程序加载的类、内存回收情况、调用的本地接口等。这时,我们可以使用-verbose命令。在Eclipse中,可以通过右键设置,也可以在命令行输入java -verbose来查看。

-verbose:class 查看类加载情况 -verbose:gc 查看虚拟机中内存回收情况 -verbose:jni 查看本地方法调用的情况

我们在本地环境,添加启动参数-verbose:class循环调用接口。 可以看到生成了无数com.alibaba.fastjson.serializer.ASMSerializer_1_WlkCustomerDto: [Loaded com.alibaba.fastjson.serializer.ASMSerializer_1_WlkCustomerDto from file:/C:/Users/yangzhendong01/.m2/repository/com/alibaba/fastjson/1.2.71/fastjson-1.2.71.jar] [Loaded com.alibaba.fastjson.serializer.ASMSerializer_1_WlkCustomerDto from file:/C:/Users/yangzhendong01/.m2/repository/com/alibaba/fastjson/1.2.71/fastjson-1.2.71.jar] [Loaded com.alibaba.fastjson.serializer.ASMSerializer_1_WlkCustomerDto from file:/C:/Users/yangzhendong01/.m2/repository/com/alibaba/fastjson/1.2.71/fastjson-1.2.71.jar] [Loaded com.alibaba.fastjson.serializer.ASMSerializer_1_WlkCustomerDto from file:/C:/Users/yangzhendong01/.m2/repository/com/alibaba/fastjson/1.2.71/fastjson-1.2.71.jar] [Loaded com.alibaba.fastjson.serializer.ASMSerializer_1_WlkCustomerDto from file:/C:/Users/yangzhendong01/.m2/repository/com/alibaba/fastjson/1.2.71/fastjson-1.2.71.jar] [Loaded com.alibaba.fastjson.serializer.ASMSerializer_1_WlkCustomerDto from file:/C:/Users/yangzhendong01/.m2/repository/com/alibaba/fastjson/1.2.71/fastjson-1.2.71.jar]

当调用了很多次接口,积累了一定数量的类时,我们手动执行Full GC,进行类加载器的回收,发现大量与fastjson相关的类被回收。

图片
image.png

在回收之前,使用jmap命令查看类加载情况,同样也可以发现大量与fastjson相关的类: jmap -clstats 7984

图片
image.png

通过这些发现,我们有了方向。这次我仔细排查了代码,查看代码逻辑中是否使用了fastjson,并发现了以下代码: /**  * 返回Json字符串.驼峰转_  * @param bean 实体类.  */ public static String buildData(Object bean) {     try {         SerializeConfig CONFIG = new SerializeConfig();         CONFIG.propertyNamingStrategy = PropertyNamingStrategy.SnakeCase;         return jsonString = JSON.toJSONString(bean, CONFIG);     } catch (Exception e) {         return null;     } }

问题根因

我们在调用wcs前将驼峰字段的实体类序列化成下划线字段,**这需要使用fastjson的SerializeConfig,而我们在静态方法中对其进行了实例化。SerializeConfig创建时默认会创建一个ASM代理类用来实现对目标对象的序列化。也就是上面被频繁创建的类com.alibaba.fastjson.serializer.ASMSerializer_1_WlkCustomerDto,如果我们复用SerializeConfig,fastjson会去寻找已经创建的代理类,从而复用。但是如果new SerializeConfig(),则找不到原来生成的代理类,就会一直去生成新的WlkCustomerDto代理类。 下面两张图时问题定位的源码:

图片
image.png
图片
image.png

我们将SerializeConfig作为类的静态变量,问题得到了解决。 private static final SerializeConfig CONFIG = new SerializeConfig();

static {     CONFIG.propertyNamingStrategy = PropertyNamingStrategy.SnakeCase; }

fastjson SerializeConfig 做了什么

SerializeConfig介绍:

SerializeConfig的主要功能是配置并记录每种Java类型对应的序列化类(ObjectSerializer接口的实现类),例如Boolean.class使用BooleanCodec作为序列化实现类,float[].class使用FloatArraySerializer作为序列化实现类。这些序列化实现类有的是FastJSON中默认实现的(如Java基本类型),有的是通过ASM框架生成的(如用户自定义类),有的甚至是用户自定义的序列化类(如将Date类型默认实现转为秒)。判断是否使用ASM生成序列化类还是使用JavaBean的序列化类取决于是否在Android环境中(通过环境变量"java.vm.name"为"dalvik"或"lemur"来判断),并且不仅仅在上述代码中有判断,后续还有更具体的判断。 理论上,每个SerializeConfig实例在序列化相同的类时,都会找到之前生成的该类的代理类进行序列化。然而,我们的服务在每次接口调用时都实例化一个ParseConfig对象来配置Fastjson的反序列化设置。在未禁用ASM代理的情况下,由于每次调用ParseConfig都是一个新的实例,所以永远也检查不到已经创建的代理类,因此Fastjson不断创建新的代理类并加载到元空间中,最终导致元空间不断扩张,耗尽机器的内存。

升级JDK1.8才会出现问题

导致问题发生的原因还是值得重视。为什么在升级之前不会出现这个问题?这就要分析jdk1.8和1.7自带的hotspot虚拟机的差异了。

从jdk1.8开始,自带的hostspot虚拟机取消了过去的永久区,而新增了metaspace区,从功能上看,metaspace可以认为和永久区类似,其最主要的功用也是存放类元数据,但实际的机制则有较大的不同。 首先,metaspace默认的最大值是整个机器的物理内存大小,所以metaspace不断扩张会导致java程序侵占系统可用内存,最终系统没有可用的内存;而永久区则有固定的默认大小,不会扩张到整个机器的可用内存。当分配的内存耗尽时,两者均会触发full gc,但不同的是永久区在full gc时,以堆内存回收时类似的机制去回收永久区中的类元数据(Class对象),只要是根引用无法到达的对象就可以回收掉,而metaspace判断类元数据是否可以回收,是根据加载这些类元数据的Classloader是否可以回收来判断的,只要Classloader不能回收,通过其加载的类元数据就不会被回收。这也就解释了我们这两个服务为什么在升级到1.8之后才出现问题,因为在之前的jdk版本中,虽然每次调用fastjson都创建了很多代理类,在永久区中加载类很多代理类的Class实例,但这些Class实例都是在方法调用是创建的,调用完成之后就不可达了,因此永久区内存满了触发full gc时,都会被回收掉。 而使用1.8时,因为这些代理类都是通过主线程的Classloader加载的,这个Classloader在程序运行的过程中永远也不会被回收,因此通过其加载的这些代理类也永远不会被回收,这就导致metaspace不断扩张,最终耗尽机器的内存了。 这个问题并不局限于fastjson,只要是需要通过程序加载创建类的地方,就有可能出现这种问题。「尤其是在框架中,往往大量采用类似ASM、javassist等工具进行字节码增强,而根据上面的分析,在jdk1.8之前,因为大多数情况下动态加载的Class都能够在full gc时得到回收,因此不容易出现问题」,也因此很多框架、工具包并没有针对这个问题做一些处理,一旦升级到1.8之后,这些问题就可能会暴露出来。

总结

问题解决了,接下来复盘下整个排查问题的流程,整个流程暴露了我很多问题,最主要的就是「对于JVM不同版本的内存分配还不够熟悉」,导致了对于老生代和元空间判断失误,走了很多弯路,在直接内存中排查了很久,浪费了很多时间。 其次,排查需要的「一是仔细,二是全面,」,最好将所有可能性先行整理好,不然很容易陷入自己设定好的排查范围内,走进死胡同不出来。 最后,总结一下这次的问题带来的收获:

  • • JDK1.8开始,自带的hostspot虚拟机取消了过去的永久区,而新增了metaspace区,从功能上看,metaspace可以认为和永久区类似,其最主要的功用也是存放类元数据,但实际的机制则有较大的不同。

  • • 对于JVM里面的内存需要在启动时进行限制,包括我们熟悉的堆内存,也要包括直接内存和元生区,这是保证线上服务正常运行最后的兜底。

  • • 使用类库,请多注意代码的写法,尽量不要出现明显的内存泄漏。

  • • 对于使用了ASM等字节码增强工具的类库,在使用他们时请多加小心(尤其是JDK1.8以后)。


转载于:https://mp.weixin.qq.com/s/j11S2GKVsZKbv3OPIMnFhw

支付宝打赏 微信打赏

如果文章对你有帮助,欢迎点击上方按钮打赏作者

 工具推荐 更多»