记一次线上JVM原生系统内存泄露排查

问题报告

一日运维报告某应用JVM进程被OOM kill
[日期] 10-15-108-158 kernel: Out of memory: Kill process 23537 (java) score 846 or sacrifice child [日期] 10-15-108-158 kernel: Killed process 23537, UID 501, (java) total-vm:6458012kB, anon-rss:3364716kB, file-rss:112kB

可以看出进程是在虚拟内存用到6.46G左右，驻留内存用到3.36G左右被OOM kill掉的。
##问题分析

应用概况

该JVM是一个大数据接口程序，供后台报表应用查询一些预计算生成的各种数据，Linux虚拟机配置了6GB内存。应用使用了大量的第三方库连接MySQL，Kylin，Druid和ES等。同时JVM启动参数配置了XX:+HeapDumpOnOutOfMemoryError选项。

初步分析

Java堆内存，MetaSpace等使用情况

从运维Zabbix系统中可以查出此JVM运行几周的堆内存和GC情况相当正常，并无堆内存泄露的情况。也并无hprof后缀的heap dump生成。
同时Meta Space也无任何泄露迹象。
监控记录显示Java线程数目也正常，并未发生线程数量剧增导致过量使用Thread Stack内存导致的泄露。

Java堆外内存分析

接着怀疑Java应用中是不是有第三方库使用了DirectByteBuffer操作堆外内存导致的泄露。但因为并未监控JVM堆外内存的使用情况，所以需要重新采集。
于是在重启的JVM启动参数中加入-XX:NativeMemoryTracking=detail，并用crontab每小时运行jcmd {PID} VM.native_memory detail > nmt.$PID.`date '+%Y-%m-%d.%H:%M:%S'`.log
来记录JVM管辖内存的变化。也运行
pmap -x $PID > pmapx.$PID.`date '+%Y-%m-%d.%H:%M:%S'`.log
来记录操作系统进程内存段分布情况。

经记录，发现Native Memory Tracking(NMT)记录的JVM管理的内存情况均正常，包括Internal部分反映的堆外内存使用情况均正常，如下所示：
- Internal (reserved=13043KB, committed=13043KB) (malloc=13011KB #19159) (mmap: reserved=32KB, committed=32KB)
既然JVM管理的内存均正常，那就只能怀疑是进程的原生内存发生了泄露。

进程原生内存分析(Native Memory)

通过上一个步骤每小时记录的pmap内存使用和分段情况可以看出，进程使用的虚拟内存和驻留(RSS)内存不断地增加，一周虚拟内存增加了2GB多。

total kB         3174032  657612  637292
total kB         3174032  681068  660744
total kB         3174032  707084  686760
total kB         3175060  732216  711884
total kB         3175060  766008  745676
.......省略几万字
total kB         5006796 3231676 3218728
total kB         5072332 3214132 3201180
total kB         5137868 3217816 3204860
total kB         5203404 3220000 3207032

在最新的pmap输出中，可以发现大概有70多个加起来是65536kB(64MB)的内存块，随着时间推移越来越多，最后导致内存不够。

00007f756c000000    1636    1540    1540 rw---    [ anon ]
00007f756c199000   63900       0       0 -----    [ anon ]
00007f7574000000    2552    1720    1720 rw---    [ anon ]
00007f757427e000   62984       0       0 -----    [ anon ]
00007f7578000000    2024    1900    1900 rw---    [ anon ]
00007f75781fa000   63512       0       0 -----    [ anon ]
00007f757c000000   14468   14436   14436 rw---    [ anon ]
00007f757ce21000   51068       0       0 -----    [ anon ]
00007f7580000000    4452    4420    4420 rw---    [ anon ]
00007f7580459000   61084       0       0 -----    [ anon ]
00007f7584000000   22908   22852   22852 rw---    [ anon ]
00007f758565f000   42628       0       0 -----    [ anon ]
00007f7588000000   51776   51584   51584 rw---    [ anon ]
00007f758b290000   13760       0       0 -----    [ anon ]
00007f758c000000   54680   54620   54620 rw---    [ anon ]
00007f758f566000   10856       0       0 -----    [ anon ]
00007f7590000000   44616   44544   44544 rw---    [ anon ]
00007f7592b92000   20920       0       0 -----    [ anon ]
00007f7594000000   65512   65484   65484 rw---    [ anon ]

而且这些64M的内存空间都不在Native Memory Tracking输出的地址段内，不属于JVM管理的内存。

原生内存详细分析

内存内容分析

使用gdb 打印出这些内存区域的内容，起始地址使用pmap输出的内存块地址起始值，结束地址将起始地址加上想输出的内存区大小。
gdb --batch --pid {PID} -ex "dump memory native_memory.dump 0x00007f7588000000 0x00007f7588001A40" 注意起始和终止地址要加上0x表示16进制
查看native_memory.dump文件，发现是

# Licensed to the Apache Software Foundation (ASF) under one
# or more contributor license agreements.  See the NOTICE file
# distributed with this work for additional information
# regarding copyright ownership.  The ASF licenses this file
# to you under the Apache License, Version 2.0 (the
# "License"); you may not use this file except in compliance
# with the License.  You may obtain a copy of the License at
#
#     http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
#driver.name=Kylin JDBC Driver
driver.version=0.1
product.name=Kylin
product.version=0.1
jdbc.compliant=true
driver.version.major=0
driver.version.minor=8
database.version.major=0
database.version.minor=8
build.timestamp=20140918-2017ication Authority - G21:08U1(c) 1998 VeriSign, Inc. - For authorized use only10U
280801235959Z01                                                                                            VeriSign Trust Network00    UUS10U
VeriSign, Inc.1<0:U3Class 1 Public Primary Certification Authority - G21:08U1(c) 1998 VeriSign, Inc. - For authorized use only10U

使用脚本统计多个64M内存块，发现90%都是类似的内容，那基本上可以定位是所使用的Kylin第三方库引入的内存泄露。由于原生内存一般是通过malloc来申请内存，所以想通过malloc的profile工具来定位具体的内存分配模块。

引入jemalloc

jemalloc的jeprof功能可以定位到原生内存的分配代码栈。通过以下步骤引入jeprof。

wget https://github.com/jemalloc/jemalloc/releases/download/5.1.0/jemalloc-5.1.0.tar.bz2
tar xvf jemalloc-5.1.0.tar.bz2
cd jemalloc-5.1.0
./configure --enable-prof --prefix=/usr/local
make
sudo make install
在启动脚本中加入export MALLOC_CONF=“prof:true,lg_prof_sample:1,lg_prof_interval:26,prof_prefix:/{YOUR INTENDED FOLDER}/jeprof.out” to run.sh
同时在java命令前加上 LD_PRELOAD="/usr/local/lib/libjemalloc.so", 变成LD_PRELOAD="/usr/local/lib/libjemalloc.so" java -Xmx… -Xms…
启动JVM
在Linux上，cd /{YOUR INTENDED FOLDER}/,
执行 jeprof --show_bytes --dot which java jeprof.out.xxxx.heap > leak_test.dot ,
jeprof.out.xxxx.heap是最新的jemalloc生成的内存统计分析.
下载leak_test.dot 到本地folder {somepath},
下载graphviz(https://www.graphviz.org/download/)
执行dot -Tpng {somepath}/leak_test.dot -o {somepath}/leak_test.png

可以看到大部分泄露是来自于java.util.zip.Inflater.inflateBytes

java.util.zip.Inflater.inflateBytes调用栈跟踪

使用阿里巴巴的https://alibaba.github.io/arthas/ 工具，attach到JVM，然后使用stack命令，可以看到以下调用栈。

$ options unsafe true
NAME    BEFORE-VALUE  AFTER-VALUE
-----------------------------------
unsafe  false         true
$ stack java.util.zip.Inflater inflate
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:2) cost in 254 ms.
ts=2019-03-24 10:20:58;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@18b4aac2@java.util.zip.InflaterInputStream.read()at java.io.FilterInputStream.read(FilterInputStream.java:133)at java.io.FilterInputStream.read(FilterInputStream.java:107)at java.util.Properties$LineReader.readLine(Properties.java:435)at java.util.Properties.load0(Properties.java:353)at java.util.Properties.load(Properties.java:341)at org.apache.kylin.jdbc.shaded.org.apache.calcite.avatica.DriverVersion.load(DriverVersion.java:104) at org.apache.kylin.jdbc.Driver.createDriverVersion(Driver.java:88)at org.apache.kylin.jdbc.shaded.org.apache.calcite.avatica.UnregisteredDriver.<init>(UnregisteredDriver.java:56) at org.apache.kylin.jdbc.Driver.<init>(Driver.java:70)at sun.reflect.GeneratedConstructorAccessor14.newInstance(null:-1)at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)at java.lang.reflect.Constructor.newInstance(Constructor.java:423)at java.lang.Class.newInstance(Class.java:442)at xxxx.util.KylinUtil.getConnection(KylinUtil.java:18)

最后发现是写业务代码的同事非常错误地重复地在获取连接时新建Driver对象所导致的。
Driver driver = (Driver) Class.forName("org.apache.kylin.jdbc.Driver").newInstance();
但进一步分析，就算是重复调用也不应该有内存泄露，接着分析Kylin JDBC Driver的代码。

Kylin JDBC Driver内存泄露分析

通过查看源代码，Kylin使用了https://github.com/apache/calcite-avatica 来实现JDBC Driver，Avatica中的代码块引入了内存泄露。

try {final InputStream inStream =driverClass.getClassLoader().getResourceAsStream(resourceName);
//      inStream没有close

重复调用这段代码放大了内存泄露的规模。已经给开源项目提了issue和pull request，下个版本应该会修复这个问题。

结论

这次内存泄露使用多种工具，最后定位到了JVM原生内存的泄露根源。技术人员碰到每一次问题，都是一次学习的机会，要沉下心来，剥丝去茧，一步步尝试去触及问题的本质，去享受云开见月明那最后一刻的喜悦。