解决JVM进程被系统杀掉问题

背景

服务A在测试环境，隔几个小时接口就无法访问。登录机器查看，发现进程已经没了。大致猜想是进程使用的内存或CPU资源使用太多，导致被系统kill。

问题定位

使用dmesg命令查看进程被kill的详情。

> dmesg --time-format iso

2024-03-05T02:45:48,770989+0000 pool-2-thread-6 invoked oom-killer: gfp_mask=0x100cca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=0
2024-03-05T02:45:48,779128+0000 CPU: 0 PID: 838 Comm: pool-2-thread-6 Not tainted 5.10.184-175.749.amzn2.x86_64 #1
2024-03-05T02:45:48,911347+0000 Mem-Info:
2024-03-05T02:45:48,914582+0000 active_anon:83 inactive_anon:455069 isolated_anon:0active_file:71 inactive_file:1104 isolated_file:32unevictable:0 dirty:0 writeback:0slab_reclaimable:4982 slab_unreclaimable:6781mapped:555 shmem:118 pagetables:2540 bounce:0free:13097 free_pcp:394 free_cma:0
2024-03-05T02:45:48,939533+0000 Node 0 active_anon:332kB inactive_anon:1820276kB active_file:1748kB inactive_file:1908kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:2220kB dirty:0kB writeback:0kB shmem:472kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB kernel_stack:8048kB all_unreclaimable? no
2024-03-05T02:45:48,958593+0000 Node 0 DMA free:7924kB min:364kB low:452kB high:540kB reserved_highatomic:0KB active_anon:0kB inactive_anon:7688kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15908kB mlocked:0kB pagetables:16kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
2024-03-05T02:45:48,977738+0000 lowmem_reserve[]: 0 1891 1891 1891
2024-03-05T02:45:48,981797+0000 Node 0 DMA32 free:44716kB min:44688kB low:55860kB high:67032kB reserved_highatomic:0KB active_anon:332kB inactive_anon:1812588kB active_file:1748kB inactive_file:1840kB unevictable:0kB writepending:0kB present:2041768kB managed:1954608kB mlocked:0kB pagetables:10144kB bounce:0kB free_pcp:2084kB local_pcp:1164kB free_cma:0kB
2024-03-05T02:45:49,003571+0000 lowmem_reserve[]: 0 0 0 0
2024-03-05T02:45:49,007346+0000 Node 0 DMA: 1*4kB (U) 2*8kB (UM) 4*16kB (UME) 5*32kB (UME) 4*64kB (UME) 4*128kB (UME) 3*256kB (UME) 2*512kB (UE) 3*1024kB (UE) 1*2048kB (U) 0*4096kB = 7924kB
2024-03-05T02:45:49,020018+0000 Node 0 DMA32: 223*4kB (UME) 118*8kB (UE) 180*16kB (UME) 300*32kB (UME) 189*64kB (UME) 31*128kB (UM) 4*256kB (UM) 0*512kB 1*1024kB (M) 4*2048kB (M) 1*4096kB (M) = 44716kB
2024-03-05T02:45:49,032871+0000 Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
2024-03-05T02:45:49,040653+0000 Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
2024-03-05T02:45:49,047994+0000 1180 total pagecache pages
2024-03-05T02:45:49,051655+0000 0 pages in swap cache
2024-03-05T02:45:49,055150+0000 Swap cache stats: add 0, delete 0, find 0/0
2024-03-05T02:45:49,059720+0000 Free swap  = 0kB
2024-03-05T02:45:49,062834+0000 Total swap = 0kB
2024-03-05T02:45:49,065939+0000 514440 pages RAM
2024-03-05T02:45:49,069266+0000 0 pages HighMem/MovableOnly
2024-03-05T02:45:49,072870+0000 21811 pages reserved
2024-03-05T02:45:49,076104+0000 0 pages hwpoisoned
2024-03-05T02:45:49,079323+0000 Tasks state (memory values in pages):
2024-03-05T02:45:49,083269+0000 [  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
2024-03-05T02:45:49,322324+0000 [   2396]     0  2396     6972       52   102400        0             0 atd
2024-03-05T02:45:49,329382+0000 [   2401]     0  2401     6171      158    94208        0             0 crond
2024-03-05T02:45:49,336441+0000 [   2421]     0  2421     2640       31    69632        0             0 agetty
2024-03-05T02:45:49,343630+0000 [   2423]     0  2423    30328       32    73728        0             0 agetty
2024-03-05T02:45:49,350830+0000 [   2471]     0  2471   180962     1854   147456        0             0 ssm-agent-worke
2024-03-05T02:45:49,358399+0000 [   2518]     0  2518     1068       27    57344        0             0 acpid
2024-03-05T02:45:49,374968+0000 [   4629]  1000  4629  1828472   445489  5488640        0             0 java
2024-03-05T02:45:49,404273+0000 [   4196]  1001  4196    31300      340    86016        0             0 bash
2024-03-05T02:45:49,413123+0000 [   8991]    89  8991    22598      254   204800        0             0 pickup
2024-03-05T02:45:49,439185+0000 oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/,task=java,pid=4629,uid=1000
2024-03-05T02:45:49,454767+0000 Out of memory: Killed process 4629 (java) total-vm:7313888kB, anon-rss:1781956kB, file-rss:0kB, shmem-rss:0kB, UID:1000 pgtables:5360kB oom_score_adj:0

在日志最后看到jvm进程被kill，原因是使用了7G的虚拟内存和1.7G的真实内存。而机器的内存是514440 pages * 4K ≈ 2G。

为什么JVM会使用1.7G内存？

JVM配置是-Xmx1500m -XX:MaxMetaspaceSize=256M，所以加起来用了1.7G，导致系统内存不足。处理的方案是：

第一步，先将-Xmx1500m改成-Xmx1024m，避免进程被jvm杀死。

然后，系统能占用这么多内存，一定是发生了内存泄露。在系统OOM时，尝试把堆内存dump出来，在JVM启动命令加上 -XX:HeapDumpPath=/tmp/java_heapdump.hprof 参数。

分析堆内存

得到堆文件后，通过MAT（Memory Analyzer Tool）进行分析内存使用情况。下载地址是：Eclipse Memory Analyzer Open Source Project | The Eclipse Foundation

注意事项
文档里写了“The minimum Java version required to run the stand-alone version of Memory Analyzer is Java 17. See JRE/JDK Sources.”，也就是运行的最低JDK版本是17.需要下载JDK17后，在MemoryAnalyzer.ini配置文件里加上JDK的路径，如下所示：
-vm
E:\\jdks\\jdk-17\\bin另外，内存解析比较耗内存，最好给MAT分配更多的内存，在配置里设置：-Xmx4096m

MAT提供了内存泄露的分析能力，在Overview→Reports→Leak Suspects就能看到分析报告。

Leak Suspects

报告里给出了3个可能的泄露点，以及对象各自占用的内存大小：

可以看到，a+b+c占用已经将近900M，我们再展开看看是什么对象占用了内存。

描述里说了一个com.microsoft.cognitiveservices.speech.SpeechSynthesizer就占用了400M内存，大部分内存都是放在Object[]数组里。

接下来我们要找到占用最大内存的SpeechSynthesizer对象，看里面那个属性造成内存泄露。

Dominator Tree

Dominator Tree能列出大对象和它们内部的对象路径。

从图中就能看到，第一个SpeechSynthesizer对象占用了400M，并且是VisemeReceived属性里的eventHandlerClients数组，包含了823个对象。数组里的元素是Text2SpeechMicrosoft类里的一个lambda对象，每个对象占用约1M。

至此，问题就很好定位了，找到eventHandlerClients数组追加元素的地方，看是否有异常。

问题的原因

泄露的地方是，我们用到了微软的文本转语音功能，要拿到Viseme信息，这个信息要通过回调接口获得，所以需要注册一个回调函数。

speechSynthesizer.VisemeReceived.addEventListener(visemeEventHandler);

原来speechSynthesizer对象每次都会创建，由于创建比较耗时，改用了预创建一批放入线程池的方式。这就导致speechSynthesizer对象会被复用，那么调用addEventListener(visemeEventHandler)，而不删掉的话，就会越来越多。解决的方案是加上removeEventListener(visemeEventHandler)方法。