java堆外内存泄漏排查

大多数Java虚拟机内存不足的问题都发生在堆上，但这一次被证明有点不同。

Java虚拟机（JVM）具有自动内存管理功能，因此Java开发人员不需要关心对象回收。但是他们仍然应该关注内存，因为内存不是无限的，我们有时确实会看到内存不足的错误。对于内存不足的问题，通常有两个可能的原因：

1. JVM的内存设置太小
2. 应用程序内存泄漏

对于第一种类型，使用更多内存很容易修复；只需更改一些JVM内存设置参数。对于第二种类型，我们需要找出泄漏的位置并在代码中修复它。今天我将分享一个JVM内存泄漏案例，它有点不同。

症状

一开始，我们注意到一些主机的垃圾回收（GC）开销已超出，CPU使用率也出现警报。GC开销在60%～70%之间，CPU忙于GC。这似乎是个内存问题。

行动

并非该应用程序的所有服务器都存在此问题，只有一些服务器存在此问题，这意味着需要花费1到2个小时到几天的时间来填充内存。为了在站点上缓解这个问题，我们首先获取了一个堆转储dump文件，然后对它们进行了临时恢复。

分析

对于GC开销问题，我们分析详细的GC日志、分析堆转储dump文件并分析源代码。

1. 分析详细的GC日志

该应用程序支持详细的GC日志，这对于分析内存问题非常有用。从下面的截图中，我们可以看到无论是年轻代还是老年代，都有大量的空闲内存，但是GC越来越占满了。

这有点奇怪，因为大多数时候，我们看到年轻一代和老一代都用光了，JVM没有足够的堆来分配新对象。这个问题并不是因为年轻代/老年代的内存不足造成的，那么问题在哪里呢？

我们都知道JVM的永久代是完整的和显式的垃圾回收调用System.gc()还可以触发完全GC。接下来，我们检查以下两种可能性：

1. 如果完整的GC是由显式System.gc()调用，我们将在GC日志中看到“system”关键字，但这次没有看到。
2. 如果它是由永久代完全触发的，我们可以很容易地在GC原始日志中识别它。从下面的GC原始日志中，我们可以看到永久生成有足够的可用内存。

详细的GC日志片段：

2018-09-13T20:23:29.058-0700: 2518960.051: [GC2018-09-13T20:23:29.059-0700: 2518960.051: [ParNew Desired survivor size 41943040 bytes, new threshold 6 (max 6) - age   1: 3787848 bytes,    3787848 total - age   2: 2359600 bytes,6147448 total : 662280K->7096K(737280K), 0.0319710 secs] 1224670K->569486K(2170880K), 0.0324480 secs] [Times: user=0.08 sys=0.00, real=0.03 secs]

2018-09-13T20:23:44.824-0700: 2518975.816: [Full GC2018-09-13T20:23:44.824-0700: 2518975.817: [CMS: 562390K->563346K(1433600K), 2.9864680 secs] 795326K->563346K(2170880K), [CMS Perm : 271273K->271054K(524288K)], 2.9869590 secs] [Times: user=2.97 sys=0.00, real=2.99 secs]

2018-09-13T20:23:58.130-0700: 2518989.123: [Full GC2018-09-13T20:23:58.131-0700: 2518989.123: [CMS: 563346K->561519K(1433600K), 2.8341560 secs] 867721K->561519K(2170880K), [CMS Perm : 271080K->271054K(524288K)], 2.8345980 secs] [Times: user=2.84 sys=0.00, real=2.83 secs]

2018-09-13T20:24:01.902-0700: 2518992.894: [Full GC2018-09-13T20:24:01.902-0700: 2518992.895: [CMS: 561519K->560375K(1433600K), 2.6886910 secs] 589208K->560375K(2170880K), [CMS Perm : 271055K->271055K(524288K)], 2.6891280 secs] [Times: user=2.69 sys=0.00, real=2.69 secs]

因此，这两种可能性已被排除。

过去，我们遇到了一个症状相似的复杂病例：年轻一代和老一代在完全气相色谱后都有700M的自由空间，而在永久代中没有问题垃圾回收System.gc()调用，但JVM继续执行完整的GC。原因是java.util.Vector在使用了大约400米内存的堆上，它试图扩展它的大小。正如JDK代码所写的，每次扩展时，它的大小都是原来的两倍，因此需要额外的800M内存来扩展。JVM找不到这么大的可用空间，所以它求助于连续的完整GC。

这一次，我们没有看到这种大的集合实例。

2. 检查应用程序日志，并找到问题

我们开始分析堆转储dump文件，但与此同时，在应用程序日志中，我们看到一条非常有用的错误消息：

java.lang.OutOfMemoryError: Direct buffer memory

这个错误指出了问题所在。

日志中的OOM错误：

INFO   | jvm 1| 2018/09/15 03:43:13 | Caused by: java.lang.OutOfMemoryError: Direct buffer memory

INFO   | jvm 1| 2018/09/15 03:43:13 |    at java.nio.Bits.reserveMemory(Bits.java:658)

INFO   | jvm 1| 2018/09/15 03:43:13 |    at java.nio.DirectByteBuffer.<init>(DirectByteBuffer.java:123)

INFO   | jvm 1| 2018/09/15 03:43:13 |    at java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:306)

直接缓冲区内存是操作系统的本机内存，由JVM进程使用，而不是JVM堆中。java nio使用它将数据快速写入网络或磁盘；无需在JVM堆和本机内存之间进行复制。Java应用程序可以设置JVM参数–XX:MaxDirectMemorySize来限制直接缓冲区内存大小。如果没有设置这样的参数，JVM可以使用所有可用OS的本机内存。在我们的例子中，我们检查了JVM的参数；它被设置为-XX:MaxDirectMemorySize=1024M，这意味着这个应用程序将直接缓冲区限制设置为1G，根据上面的日志，这个1G的本机内存已经用完，然后抛出OOM错误。

3. 在堆转储中查找直接内存问题

尽管直接缓冲区内存在堆外，即堆外内存，JVM仍然会处理它。每次JVM请求直接缓冲内存时，都会有一个java.nio.DirectBuffer实例在堆中表示它。此实例具有本机内存地址和此内存块的大小等。由于DirectBuffer实例的生命周期由JVM管理，因此GC线程可以在没有引用它的情况下收集它。当jvm gc线程收集DirectBuffer实例时，也可以释放关联的本机内存。

为什么这个应用程序需要超过1G的直接缓冲内存？为什么它不在整个GC期间释放内存？既然我们有了垃圾堆，我们能从中找到任何线索吗？正如我们刚才提到的，堆中的DirectBuffer对象有一些关于直接缓冲区内存的信息。

从应用程序错误日志中，JVM尝试创建一个新的DirectByteBuffer实例。我们先查一下DirectByteBuffer。在OQL中，我们看到堆中有很多DirectByteBuffer实例，而没有看到其他DirectBuffer实例，比如DirectCharBuffers。

我们可以确认这些DirectByteBuffers在这个OQL查询中使用了多少本机内存：

SELECT x, x.capacity FROM java.nio.DirectByteBuffer x WHERE ((x.capacity > 1024 * 1024) and (x.cleaner != null)) //here we only care objects whose capacity is bigger than 1M

DirectByteBuffer中的capacity字段表示DirectByteBuffer实例中请求了多少内存。这里我们用：x.cleaner！=null，这意味着我们跳过切片的DirectByteBuffer实例，这些实例只是其他DirectByteBuffer实例的视图。在这个转储中，有许多DirectByteBuffer对象的容量小于1M；我们只跳过它们。结果是：

在这个结果中，有25个实例拥有超过1M的本机内存。最大的是179M（188124977/1024/1024），其次是124M（130804508/1024/1024）。前25个实例的总和几乎是1G，这就是为什么1G的直接缓冲区内存被用完了。

4. 为什么这些DirectByteBuffer不被GC收集？

如果这些DirectByteBuffer实例是由GC收集的，那么直接缓冲区本机内存也可以释放。为什么GC线程不能收集这些DirectByteBuffer实例？

我们进一步检查参考链。从中，我们可以清楚地看到，有一些线程本地缓冲缓存保存着DirectByteBuffer的引用，这些线程本地对象属于一些守护进程线程，比如Tomcat守护进程线程。这就是为什么不能收集，如下参考链截图所示：

是谁把这些DirectByteBuffers放在这些线程本地缓存中的？为什么不把它们去掉呢？

在引用链之后，我们查看了sun.nio.ch.Util.java class。在这个类中，您将看到线程本地缓冲缓存，以及方法：getTemporyDirectBuffer（int），它将DirectByteBuffer对象放入BufferCache中。这个getTemporaryDirectBuffer由JDK的NIO类中的一些方法调用。此外，如果线程请求不是更大的直接缓冲区本机内存，则BufferCache将重用DirectByteBuffer。JDK NIO类使用这些线程本地DirectByteBuffer实例，但如果该线程处于活动状态，则不释放它们。

从上面的分析来看，问题出在JDK的代码中。这被确定为JDK问题。在JDK 8u102更新发行说明中，一个新的系统属性，jdk.nio.maxCachedBufferSize已添加以修复此问题。但在本说明中，它也指出，这个参数只能解决部分问题，而不是所有情况。

修复内存泄露

大多数情况下，您的应用程序不会有这个问题，因为您的线程是短生命线程，其中·BufferCache和DirectByteBuffer由GC线程收集，直接缓冲区本机内存释放给操作系统，或者因为每次您只需要很少的直接缓冲区内存，而JVM将重用它们。当只有多个线程是长寿命线程，并且这些线程请求越来越直接的缓冲区内存，直到达到最大直接缓冲区限制或所有内存都用完时，您将看到这个问题。

在我们的例子中，应用程序尝试为上传的文件分配一些直接缓冲区本机内存，Tomcat的守护进程线程处理这些请求。有一些非常大的上传文件，有的超过了100M，应用程序为Tomcat打开了40个守护线程，最后达到了1G直接缓存上限。

为了解决这个问题，应用程序应该在使用NIO实用程序之前将字节拆分为小字节。这可以在应用程序逻辑中更改。

总结

大多数情况下，我们会在堆上看到内存不足的问题，但它可能发生在直接缓冲区上。当直接缓冲区本机内存用完时，即使它不在堆上，属于堆外内存，我们仍然可以使用堆转储来帮助分析根本原因。