记一次JVM优化导致的堆外内存泄露bug

3,057 阅读7分钟

本文记录了一个稳定运行很久的系统在没有任何代码改动的情况下突然发生堆外内存泄露的故障排查过程。这本来是去年碰到的一个问题,但是懒癌发作一直都扔在这里没总结。新年新气象,这次就趁机把欠的债还掉好了。

起因

一天夜里零点大量线上服务突然开始报错,根据错误链路定位到是我负责的系统挂掉了_(:з」∠)_ 赶快登上机器想看下什么问题,结果服务器完全没有响应,只能求助运维将机器强行重启。重启完观察了一段时间发现服务运行平稳,危机暂时解除。

问题分析

问题定位

查看监控&日志

服务挂了第一反应自然是去看监控。从内存监控中(图1)可以明显看出零点的时候堆内存使用平稳而进程占用的内存飙升,因此怀疑很可能是出现了堆外内存泄露(前面一段空白是因为我想起来截图的时候之前的数据已经清掉了)。通过dmesg命令查看系统日志证实了确实是物理内存耗尽导致系统干掉了Tomcat进程造成服务不可用。然而当我想去通过oom dump查看当时的堆内存使用情况时发现oom dump只是在堆内存发生OutOfMemoryError时才会生成,对于堆外内存JVM则无能为力。线索在这里暂时断掉了。

图1 堆内存和进程内存监控

添加报警&导出dump文件

因为没办法复现当时的故障场景,因此找运维增加了内存使用率的报警准备观察是否还会发生。幸好(不是)没过几天就出现报警了,赶快找运维导出dump文件开始排查。

通过MAT分析dump文件

使用MAT导入dump文件,一打开就贴心的问我是不是想生成Leak Suspect,果然很懂。报告显示sun.java2d.Disposer这个对象的一个名为records的HashTable里持有大量的对象(图2)。看了下代码这个Disposer类是用来释放资源的,通过Disposer#addObjectRecord方法将对象和对应的DisposerRecord加入records中,对象被回收后会加入ReferenceQueue,一个名为'Java2D Disposer'的Daemon线程会扫描ReferenceQueue里被回收的对象并从records中取出对象对应的DisposerRecord执行DisposerRecord#dispose方法释放资源。看到这里大概可以猜到由于某种原因一个申请了堆外内存的对象一直没有被GC回收,导致其dispose方法一直得不到执行,无法释放它占有的堆外内存。

图2 MAT定位到可能发生泄露的对象
然而到了这里就无法再往下追踪了。如果试图通过outgoing references功能查看HashTable的Entry里引用的类(图3),我们只能看到WeakReference是Entry的key,而其它的class都是DisposerRecord的实现类,并不知道是因为哪个对象没有被回收导致的堆外内存没有释放。因此还需要借助其它工具来定位是具体哪个类申请的堆外内存。

图3 Disposer的records属性里引用的类

通过gperftools跟踪内存分配过程

gperftools的原理是将malloc的调用替换为它自己的tcmalloc,从而统计所有内存分配的行为。具体的用法这里写过就不再赘述了。前面可以看到Disposer$records持有的对象都是和Font相关的,我们代码里只有一处生成图片的地方用到过字体相关的代码,因此将相关代码抽出来通过gperftools跟踪内存分配过程,最终可以看到在T2KFontScaler#initNativeScaler方法里进行了堆外内存的分配(图4)。

图4 gperftools跟踪到的内存分配链路

定位故障代码

找到堆外内存分配的入口后就简单多了,慢慢debug代码,最终可以看到在Font2D#getStrike方法中创建的FileFont对象最终通过FileFont的scaler属性持有T2KFontScaler对象的引用,然后Font2D$strikeCache中又保存了FileFont对象的软引用,这就导致如果创建的FileFont如果没有被及时回收,那T2KFontScaler#dispose方法就一直无法执行,导致占用的堆外内存一直得不到释放。

public abstract class Font2D {
    private FontStrike getStrike(FontStrikeDesc var1, boolean var2) {
        FontStrike var3 = (FontStrike)this.lastFontStrike.get();
        if (var3 != null && var1.equals(var3.desc)) {
            return var3;
        } else {
            Reference var4 = (Reference)this.strikeCache.get(var1);
            if (var4 != null) {
                var3 = (FontStrike)var4.get();
                if (var3 != null) {
                    this.lastFontStrike = new SoftReference(var3);
                    StrikeCache.refStrike(var3);
                    return var3;
                }
            }

            if (var2) {
                var1 = new FontStrikeDesc(var1);
            }

            var3 = this.createStrike(var1);
            int var5 = var1.glyphTx.getType();
            if (var5 != 32 && ((var5 & 16) == 0 || this.strikeCache.size() <= 10)) {
                var4 = StrikeCache.getStrikeRef(var3);
            } else {
                var4 = StrikeCache.getStrikeRef(var3, true);
            }

            this.strikeCache.put(var1, var4);
            this.lastFontStrike = new SoftReference(var3);
            StrikeCache.refStrike(var3);
            return var3;
        }
    }
}

故障原因

回到故障本身来,这个系统已经稳定运行了很久代码也没有改动,为什么突然就出现了这个问题呢?原来是几天前为了准备大促做了一次压测,当时发现GC耗时比较长并且大约每2小时就会发生一次FullGC,因此适当增加了堆内存的大小以避免FullGC的发生。那么问题就来了,堆内存增大意味着strikeCache里持有的FontStrike软引用变多了,那么通过FontStrike持有的T2KFontScaler对象占用的堆外内存也增多了。并且因为FullGC频率降低了FontStrike的软引用不会及时被回收,导致T2KFontScaler的Disposer一直无法去释放分配的堆外内存。而堆内存增大的同时堆外内存也相应的变小了,一增一减导致堆外内存在堆内存占满触发FullGC释放空间之前就耗尽了,最终触发了Linux的oom-killer机制干掉了整个Tomcat进程以释放内存。

解决方案

找到问题原因后解决方案就比较简单了。可以通过启动参数'-Dsun.java2d.font.reftype=weak'让FontStrikeCache持有弱引用以及时释放内存。而我们的系统使用的字体其实只有几种,因此将字体作为静态变量在项目启动的时候初始化好而不是每次请求都去新建字体就可以解决这个问题了。

后记

这次我们通过MAT的Leak Suspect功能定位出了可能发生泄漏的对象并定位到对应的代码块,然后通过gperftools追踪到实际分配堆外内存的方法,最终定位到了堆外内存泄露的原因。但是如果代码块不好定位,或者堆外内存不是通过malloc方法分配的又该怎么办呢,只用MAT有办法定位原因吗?实际上我们再回头仔细看Disposer$Entry里引用的类(图3),WeakReference是Entry的key,其它的class都是DisposerRecord的实现,这就意味着它们会在DisposerRecord#dispose方法里实现释放资源的逻辑。那么只要dispose方法里有释放内存的逻辑,就说明内存是这个类申请的。那么挨个看过去很容易找到T2KFontScaler的dispose方法里通过disposeNativeScaler这个本地方法进行了内存的释放。

class T2KFontScaler extends FontScaler {
    private synchronized void disposeScaler() {
        this.disposeNativeScaler(this.nativeScaler, this.layoutTablePtr);
        this.nativeScaler = 0L;
        this.layoutTablePtr = 0L;
    }

    public synchronized void dispose() {
        if (this.nativeScaler != 0L || this.layoutTablePtr != 0L) {
            Runnable var2 = new Runnable() {
                public void run() {
                    T2KFontScaler.this.disposeScaler();
                }
            };
            (new InnocuousThread(var2)).start();
        }
    }
}

此外sun.font.StrikeCache$SoftDisposerRef的命名其实也指出了这个对象是个软引用,点击去可以看到它确实持有T2KFontScaler的引用。因此只用MAT其实也是可以定位到具体的泄露位置的。

总结

本文记录了一次因为堆内存调优而暴露出的堆外内存泄露问题的排查过程。首先通过监控和系统日志判断出可能发生了堆外内存泄露,然后获取再次发生泄露时的dump文件并通过MAT工具定位到可能的泄露代码,之后通过gperftools追踪到实际分配内存的类并从源码中定位到发生泄漏的代码,最后结合项目近期的JVM优化查明了故障发生的原因并进行了修复,此外在回顾了整个故障排查的过程后也总结出了更直接的使用MAT定位问题原因的方法。
鸽了半年多终于把自己这个坑给填上了,平时各种故障调优的书和文章看了不少,实际碰到问题了排查的时候还是思路不清晰走了许多弯路,光一个MAT里各种工具的用法就够折腾的了,所以说纸上得来终觉浅,绝知此事要躬行。借着这次故障也学到了不少新东西,例如linux的系统日志和oom-killer、堆外内存分配回收机制、还有各种内存分析工具的使用等等。新年开始要养成一个好的习惯,把平时学到的东西都记录下来。

参考文档

记一次Font导致JVM堆外内存泄漏分析
Font.create()引发OOME问题
macOS上使用gperftools定位Java内存泄漏问题