背景
服务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:0
active_file:71 inactive_file:1104 isolated_file:32
unevictable:0 dirty:0 writeback:0
slab_reclaimable:4982 slab_unreclaimable:6781
mapped:555 shmem:118 pagetables:2540 bounce:0
free: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)方法。
总结
遇到问题的时候,通过dmesg命令确定进程是被系统kill。然后,用 -XX:HeapDumpPath命令拿到堆信息。最后,通过MAT工具分析内存泄露的地方。