Java应用堆外内存泄漏排查

背景

我司商城系统生产服务隔一段时间就挂掉一次，所有的机器都有这个问题，而且问题出现的越来越频繁，从最开始的半个月一次，到后来一周一次、3天一次，一直到最后的1天1次甚至2次，导致服务极其不稳定，查找泄漏源成了迫切要解决的问题

初步排查和猜测

1、首先获取应用pid

ps -ef|grep marketing-center

2、根据pid查询java应用堆内存使用情况，以及应用进程占用系统内存情况

#查看java程序GC情况以及堆内内存使用情况
jstat -gc $pid 2000
#结果如下
[www@idc06-c-marketingcenter-03 ~]$ jstat -gc 14626 2000
 S0C   S1C   S0U   S1U     EC       EU       OC         OU       MC     MU   CCSC   CCSU   YGC     YGCT   FGC   FGCT     GCT  
 0.0   65536.0  0.0   65536.0 2068480.0 737280.0 3436544.0   258445.0  98432.0 92081.3 11392.0 10229.1    191   11.714   0      0.000   11.714
 0.0   65536.0  0.0   65536.0 2068480.0 925696.0 3436544.0   258445.0  98432.0 92081.3 11392.0 10229.1    191   11.714   0      0.000   11.714
 0.0   65536.0  0.0   65536.0 2068480.0 1118208.0 3436544.0   258445.0  98432.0 92081.3 11392.0 10229.1    191   11.714   0      0.000   11.714
 0.0   65536.0  0.0   65536.0 2068480.0 1372160.0 3436544.0   258445.0  98432.0 92081.3 11392.0 10229.1    191   11.714   0      0.000   11.714
 0.0   65536.0  0.0   65536.0 2068480.0 1554432.0 3436544.0   258445.0  98432.0 92081.3 11392.0 10229.1    191   11.714   0      0.000   11.714
 0.0   65536.0  0.0   65536.0 2068480.0 1667072.0 3436544.0   258445.0  98432.0 92081.3 11392.0 10229.1    191   11.714   0      0.000   11.714
 0.0   65536.0  0.0   65536.0 2068480.0 1699840.0 3436544.0   258445.0  98432.0 92081.3 11392.0 10229.1    191   11.714   0      0.000   11.714
 0.0   65536.0  0.0   65536.0 2068480.0 1839104.0 3436544.0   259483.3  98432.0 92081.3 11392.0 10229.1    191   11.714   0      0.000   11.714
 0.0   65536.0  0.0   65536.0 2068480.0 1880064.0 3436544.0   259483.3  98432.0 92081.3 11392.0 10229.1    191   11.714   0      0.000   11.714
 0.0   51200.0  0.0   51200.0 2082816.0 274432.0 3436544.0   245594.6  98432.0 92081.3 11392.0 10229.1    192   11.786   0      0.000   11.786
 0.0   51200.0  0.0   51200.0 2082816.0 321536.0 3436544.0   245594.6  98432.0 92081.3 11392.0 10229.1    192   11.786   0      0.000   11.786
 
#查看应用进程占用系统内存情况，可以用top代替
ps -p $pid -o rss,vsz
#结果如下：
[www@idc06-c-marketingcenter-03 ~]$ ps -p 14626 -o rss,vsz
 RSS   VSZ
12303720 19423396

根据以上信息可以看出，堆内内存使用也就5G左右，但是Java应用实际占用内存却高达12G左右，而且堆内内存一切正常，Young GC也比较正常平稳，Full GC也保持在一个较低的频率，通过以上数据基本可以断定发生了Java堆外内存泄漏，为了验证我的猜想，使用pmap命令查看一下系统内存分配

#查看系统内存分配情况
pmap -x $pid | sort -k3 -n
#结果如下，内容较多，截取关键部分展示
[www@idc06-c-marketingcenter-03 ~]$ pmap -x 14626 | sort -k3 -n
...
00007f44d8000000   65536   64712   64712 rw---   [ anon ]
00007f4578000000   65508   64744   64744 rw---   [ anon ]
00007f44d4000000   65524   64860   64860 rw---   [ anon ]
00007f43fc000000   65536   64996   64996 rw---   [ anon ]
00007f4464000000   65508   65004   65004 rw---   [ anon ]
00007f4528000000   65536   65044   65044 rw---   [ anon ]
00007f43dc000000   65536   65060   65060 rw---   [ anon ]
00007f45a4000000   65524   65148   65148 rw---   [ anon ]
00007f43d0000000   65508   65156   65156 rw---   [ anon ]
00007f45a0000000   65516   65180   65180 rw---   [ anon ]
...

发现大量64MB左右的内存块，且分配地址在堆外，以上内容验证了我的猜想，确实有堆外内存泄漏

详细排查经过

由于是堆外内存泄漏，JDK自带的工具已经不好用了，首先借助谷歌的内存分配监测工具gperftools来排查具体哪段代码进行了堆外内存申请，具体安装使用请参考：Java直接内存泄漏排查工具gperftools使用方法

#结果较多，截取部分
Total: 125704.3 MB
 94257.6  75.0%  75.0%  94257.6  75.0% updatewindow
 20573.0  16.4%  91.3%  20573.0  16.4% inflateInit2_
  9946.9   7.9%  99.3%   9946.9   7.9% os::malloc@91de80
   457.8   0.4%  99.6%    457.8   0.4% init
   253.1   0.2%  99.8%  20826.1  16.6% Java_java_util_zip_Inflater_init
   149.0   0.1%  99.9%    149.0   0.1% readCEN
    38.4   0.0% 100.0%     38.4   0.0% __GI__dl_allocate_tls
    14.7   0.0% 100.0%     14.7   0.0% deflateInit2_
     3.8   0.0% 100.0%    156.2   0.1% ZIP_Put_In_Cache0
     2.4   0.0% 100.0%      2.4   0.0% _dl_new_object
     2.2   0.0% 100.0%      2.2   0.0% newEntry
     1.3   0.0% 100.0%      1.3   0.0% __GI___strdup
     0.9   0.0% 100.0%      0.9   0.0% __res_context_send
     0.7   0.0% 100.0%      0.7   0.0% JLI_MemAlloc
...

通过分析结果我们可以将目光聚焦在updatewindow与Java_java_util_zip_Inflater_init上，由于updatewindow不是Java方法申请的内存，我们可以忽略不计，将重心放在Java Native 方法Java_java_util_zip_Inflater_init上，根据这个结果我们可以去项目中搜索所有使用Inflater类的代码，最终将范围缩小到GZIPInputStream与GZIPOutputStream这两个类，但是由于项目中使用这些类的地方还是比较多，所以依然无法确认问题代码

定位问题代码并解决

使用 gdb 命令 dump 出了那些64M的内存块，然后通过查看dump出来的结果最终定位到问题

注意：dump内存会挂起应用进程，一定要确保没有流量流入再使用

1、找出那些64MB内存的地址

#命令
less /proc/$pid/smaps
#结果
[www@idc06-c-marketingcenter-07 ~]$ less /proc/14626/smaps
7f43dc000000-7f440e000000 ---p 00000000 00:00 0
Size:              65536 kB
Rss:               65536 kB
Pss:               65044 kB
Shared_Clean:          0 kB
Shared_Dirty:          0 kB
Private_Clean:         0 kB
Private_Dirty:         0 kB
Referenced:            0 kB
Anonymous:         65536 kB
AnonHugePages:         0 kB
Swap:                  0 kB
KernelPageSize:        4 kB
MMUPageSize:           4 kB
Locked:                0 kB
VmFlags: rd wr mr mw me ac sd
...

2、使用gdb命令dump出内存

#先连接程序
gdb -pid $pid
#进入gdb调试模式dump内存
dump memory mem.bin 7f43dc000000 7f440e000000
#mem.bin是内存dump出来的文件，后面是地址
strings mem.bin > mem.log  #将二进制文件读取成字符串并输出到文件，方便查阅
less mem.log

内存dump文件内容如下：

[www@idc06-c-marketingcenter-03 ~]$ less mem.log
...
com.xxx.marketing.domain.dto.GroupProductItemAi&$*^@($)-jtsjrns?:]][\\..,;0&^(
=-com.xxx.marketing.domain.dto.GroupProductItemAi&$*^@($)-jtsjrns?:]][\\..,;0&^(
=-com.xxx.marketing.domain.dto.GroupProductItemAi&$*^@($)-jtsjrns?:]][\\..,;0&^(
=-&$*^@($)-jtsjrns?:]][\\..,;0&^(=-com.xxx.marketing.domain.dto.GroupProductItemAi
...

上图省略了一部分内容，我发现很多个64MB文件全都是GroupProductItemAi对象，最后终于肯定泄漏的对象就是 marketing-center 中的 POJO com.mryt.marketing.center.domain.GroupProductItemAi然后在项目中全局搜索该POJO然后根据上面得到的GZIPInputStream与GZIPOutputStream直接申请内存等关键信息定位到最终的问题代码

/**
 * 问题代码
 */
public Map<String, T> hgetAllObject(String key, int seconds) {
    if (key == null) {
        return null;
    }
    Map<byte[], byte[]> hMap = null;
    ShardedJedis commonJedis = null;
    Map<String, T> returnMap = null;
    T object = null;
    try {
        commonJedis = jedisPool.getResource();
        hMap = commonJedis.hgetAll(key.getBytes());
        if (hMap == null) {
            return null;
        }
        returnMap = new HashMap<String, T>();
        Set<byte[]> keySet = hMap.keySet();
        ByteArrayInputStream i = null;
        GZIPInputStream gzin = null;
        ObjectInputStream in = null;
        // 这里循环创建了i gzin in等三个对象的多个副本
        for (Iterator<byte[]> it = keySet.iterator(); it.hasNext(); ) {
            byte[] keyItem = it.next();
            byte[] valueItem = hMap.get(keyItem);
            // 建立字节数组输入流
            i = new ByteArrayInputStream(valueItem);
            // 建立gzip解压输入流
            gzin = new GZIPInputStream(i);
            // 建立对象序列化输入流
            in = new ObjectInputStream(gzin);
            // 按制定类型还原对象
            object = (T) in.readObject();
            returnMap.put(new String(keyItem), object);
        }
        // 这里只释放了最后一个，造成了中间对象没有调用close方法释放内存
        if (i != null && gzin != null && in != null) {
            i.close();
            gzin.close();
            in.close();
        }
        if (seconds > 0) {
            commonJedis.expire(key, getRealCacheTime(seconds));
        }
    } catch (Exception e) {
        jedisPool.returnBrokenResource(commonJedis);
        RedisException.exceptionJedisLog(logger, key, commonJedis, e, "hgetAllObject");
        commonJedis = null;
    } finally {
        if (commonJedis != null) {
            jedisPool.returnResource(commonJedis);
        }
    }
    return returnMap;
}

上面的代码在for循环里创建了多个GZIPInputStream但是却只在for循环之后释放了最后一个GZIPInputStream对象，所以造成了大量的内存泄漏，至此，终于找到了泄露源，然后根据业务情况选择修复方式即可。