现象:
operation服务持续内存增长不释放导致超过80%阈值告警,通过观察内存不会下降,而且占用内存为14G超过了jvm 参数 -Xmx10G 的限制
排查
查看容器内存监控发现:内存确实从启动之后就开始一直增长,并且不释放
top命令也能看到java进程确实占用了14G物理内存
当前jvm启动参数如下:
-Xms10g -Xmx10g -server -verbose:gc
-Xloggc:/home/work/logs/applogs/gc_%t.log
-XX:ErrorFile=vmerr.log
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/home/work/logs/applogs/
-XX:+DisableExplicitGC
-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps
-XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:+PrintReferenceGC
-XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=512m -XX:ReservedCodeCacheSize=256m
-XX:InitialCodeCacheSize=256m -XX:+PrintAdaptiveSizePolicy -XX:+UseG1GC
-XX:MaxGCPauseMillis=200 -XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest
-XX:CompressedClassSpaceSize=128m
-Djava.library.path=/opencv-3.4.3/build/lib
-XX:+UseStringDeduplication
-XX:ParallelGCThreads=4 -XX:+AlwaysPreTouch
从上面的现象结合启动参数我们很容易判断这是堆外内存泄漏了(为什么?因为启动参数只分配了10g的堆,加上metadata 512m 也不过11g以内,现在用了14g肯定是还有其他堆外内存使用)。
为了弄清楚14g花在哪里了,我们需要跟踪一下Native Memory,在jvm启动参数里增加参数
-XX:NativeMemoryTracking=detail ,此参数能跟踪整个jvm的native层面的内存分配详情,部署上线后,我们去看看 native memory的分布。
使用jcmd命令查看一下Native内存的情况(jcmd 命令使用说明见 Native Memory Tracking)
从图上能明显的看出两部分有问题:
(1)线程数量4677个,committed 4806928KB 物理内存
(2)Internal部分 committed=2064420KB
线程数量多
我们知道每个线程的stack默认是1M,请注意并不是说线程一创建就会占用1M物理内存,实际上线程的stack默认1M是最大值,实际占用多少会随着stack的增长而增长。4677个线程就会占用 4677 * 1024 = 4789248KB,我们从图上能看到 Thread 部分总 committed=4829222KB,stack 的 committed=4806928KB,数据有点对不上,这说明JVM内部除了我们Java层面的stack之外,还有一些其他的辅助数据结构占用内存,我们用 jcmd 1 VM.native_memory detail命令详细看看thread stack部分的内存分配,可以看到reserved and committed 1028KB for Thread Stack,一个线程分配 1028K,确实比1M多一点。
总之是因为thread count太多了导致占用4.5G物理内存,我们要看看是什么线程这么多,用 jstack 1 将线程dump下来,结果如下:
为了找出每一种类线程的个数,需要做一定的分析工作,以下结果为正则表达式+手工处理得出:第一列为数量,第二列为线程代表名称(这个名字是我自己起的,意思是代表这一类线程,因为很多线程有相同的前缀后面是数字)
可以看到是 NettyClientPublicExecutor 线程太多了,其次 DubboServerHandler 线程也不少,我们需要处理这2类。
先看看NettyClientPublicExecutor线程,从代码里搜索发现这是rocketmq的netty client相关的线程,但是这个线程默认是cpu核数,除非我们自己指定,一般情况下我们很少去改它
既然一个 NettyRemotingClient 的线程是cpu核数,那么是不是因为 NettyRemotingClient 对象太多导致 NettyClientPublicExecutor 线程多呢?用 jmap -histo 1 | grep 'NettyRemotingClient'看看,结果如下:
只有21个 NettyRemotingClient 对象,但是 NettyClientPublicExecutor 线程有2589个,2589 / 21 = 123,这说明下面这行源码返回的cpu核数绝对不是我们容器的核数(容器规则4C16G)
private int clientCallbackExecutorThreads = Runtime.getRuntime().availableProcessors();
去看看容器宿主机的规格:128C,我们猜测是 Runtime.getRuntime().availableProcessors()拿到了宿主机的核数而不是容器本身的。
通过搜索我们发现 1.8.0_131 版本之前的jdk有bug(见谈JVM参数GC线程数ParallelGCThreads合理性设置-京东云开发者社区),无法识别容器环境。
查看我们使用的版本正是1.8.0_131,但是看起来仍然有问题。
Internal占用大
从 jcmd 1 VM.native_memory detail的结果看Internal部分内存通过mmap方式分配了32k,并且分配的内存起始地址有记录,但是通过malloc调用分配的2081504KB内存没有具体的地址,所以我们无法通过gdb工具去dump这部分内存,不太好排查。
从官网上看NMT无法跟踪非JVM代码分配的内存,也就是说 2081504KB 不是JVM 代码分配的,那么还有什么地方会分配呢?
operation项目比较特殊,它使用了opencv库,猜测是opencv库自己通过native方法分配了内存,从代码上看,使用了opencv实现人脸检测,可以看到使用的 opencv 相关的native 对象都没有主动进行销毁,但是这些类重写了finalize方法进行堆外内存释放,也就是说必须等gc的时候才有可能释放内存,先主动释放内存处理看看效果。
效果:
升级jdk版本后,由于jdk bug导致线程多的问题已解决,升级后线程数量在1k多,已符合预期。
opencv 对象主动释放后,内存变化从 90.7% -> 74.7% ,有明显的下降。但是单看灰度机器的内存仍然是缓慢持续增长,一直在74%左右,top命令也能看到res:0.013t,比我们配置的Xmx10G高出不少。
jcmd观察灰度机器,Thread数量已正常,Internal部分(255M)跟之前 2G 比也下降了不少,但是总committed=13263166KB(12.6G)跟容器内存占用 0.013T相比数据对不上。
再排查
由于jcmd观察到的committed=13263166KB(12.6G),与top命令观察到的0.013t(13.312G) 有差距,那容器内存持续缓慢增长到底是JVM之外的内存在长还是JVM内部内存在长?目前我们不得而知。
我们先使用 jcmd 1 VM.native_memory baseline 获取基线,等容器内存占用再增长一些后,我们再使用jcmd 1 VM.native_memory detail.diff 观察下这段时间 native memory的变化,这样大致可以判断出是jvm的native memory增长导致容器内存增长还是其他的。
2024-06-24 发现容器内存涨了接近1G,jcmd 1 VM.native_memory detail.diff发现JVM native memory上涨了227917KB=222MB,其中Thread上涨了140MB
JVM native memory增长比容器内存增长少很多,这说明可能存在其他的堆外内存泄漏。
用 pmap -x 1 | sort -n -k 3 -r 看一下进程的内存映射,结果如下,RSS=15414964KB
从网上能搜到的java 堆外内存泄漏大多是64M问题,但是我们这个并不是,从pmap结果看并没有很多64M内存分配。
持续跟踪了2天,通过pmap分配的地址和jvm native memory地址进行对比能确认就是因为堆外内存申请导致内存增长,期间多次使用pmap保存结果进行对比能发现有一定规律,容器内存增长一些后,通过两次的pmap结果对比能发现大部分是因为18~20M的内存块分配导致,用gdb dump此部分内存后strings命令看不出什么东西,都是乱码,排查就此陷入僵局。
等后面有时间了用gperftools再次跟踪下此问题。