2
头图
原创:扣钉日记(微信公众号ID:codelogs),欢迎分享,非公众号转载保留此声明。

简介

在之前的OOM问题复盘之后,本周,又一Java服务出现了内存问题,这次问题不严重,只会触发堆内存占用高报警,没有触发OOM,但好在之前的复盘中总结了dump脚本,会在堆占用高时自动执行jstack与jmap,使得我们成功保留了问题现场。

查看堆占用分布

发现有heapdump文件后,我立马拷贝到本机,并使用MAT分析,如下:
mat
很显然,好像是什么接口分配了非常大的String对象,一个String对象约200MB,那它是哪分配的呢?

查找大对象分配线程

这个分配行为肯定是某个线程做的,而线程是最常见的GC Root,因此只要查找对象的GC Root即可,如下:
gc_root
找到了大对象对应的分配线程是http-nio-8088-exec-6,如下:
image_2023-04-21_20230421200748

查看线程栈

如何查看这个线程在干什么呢?在MAT中摸索了一会,没找到相关内容,回想起我们的dump脚本中记录了jstack,打开看看,如下:
jstack
可以发现,这个线程正在做json序列化,但我仔细找了好一会,也没有找到相关接口的Controller,这是因为线程已经执行完了Controller里面的逻辑,之后返回接口响应数据时分配的大对象。

可是,线程栈中没有业务代码,就没法定位是哪个接口有问题了。。。

检查accesslog日志

考虑到分配大对象的接口肯定会很慢,于是我转向查看tomcat的accesslog日志,如下:
accesslog
终于,找到了问题接口,这个接口是用来查询商品数据的,当输入3时会查询出所有3开头的商品,而这有20w+数据,解决问题很简单,加个limit完事。

排查过程复盘

然而,我一直有个习惯,就是解决一个问题后,我会反思一下问题解决过程中有多少运气成分。

如果你经常阅读排查问题类的技术文章,就会发现不少文章,中间突然有一步定位到了问题根因,可能是突然发现了一个线索,或是硬看代码看出来的,或是猜测某处有问题,我觉得这种排查过程都有不少运气成分,我希望问题是通过多年理论基础的积累和对诊断工具的熟练使用,而有章法的一步步查出来的。

而上面通过accesslog能够定位到问题,有一定的运气成分,因为本次内存问题不极端,如果此接口请求量大,那就会瞬间触发多次FGC,进而会影响其它接口也变慢,进而无法分辨出哪个是导致问题的接口!

我想,从理论上来说,Java堆文件里面,应该有线程栈以及线程栈上的参数,因为线程是对象,参数也是对象,它们理应都在堆里,于是我找了个空闲时间,又摸索起MAT这个工具了。

MAT查看线程栈

摸索了一会,我就发现有这样一个按钮,可以查看线程信息,如下:
mat_thread

找到前面说的线程http-nio-8088-exec-6,展开后,就可以发现线程栈以及栈上的参数,如下:
mat_thread_stack

这就找到了请求的Request参数对象,再将Request对象多次展开后,就可以找到接口url信息,如下:
mat_request
嗯,这样分析heapdump文件真tm的高效啊😁

MAT下载地址:https://www.eclipse.org/mat/downloads.php

VisualVM查看线程栈

考虑到不少同学习惯用VisualVM分析heapdump,这里也放一下VisualVM的使用方法。

首先,加载heapdump文件,如下:
VisualVM_open

然后选择相应对象,右键选择Select in Threads,如下:
image_2023-04-21_20230421211033

定位到线程栈后,找到要查看的Request对象,点击进入,如下:
image_2023-04-21_20230421211738

同样,展开Request对象后,可找到url信息,如下:
image_2023-04-21_20230421211858

VisualVM下载地址:https://visualvm.github.io/download.html

总结

虽然我也用MAT很多次了,但每次问题都太简单,以至于没有深入使用过MAT,导致到现在才知道有如此便捷的分析路径。

如果你对我们的自动dump脚本感兴趣,可看看我之前写的这两篇文章。
一次线上OOM问题的个人复盘
jmap执行失败了,怎么获取heapdump?


扣钉日记
90 声望10 粉丝

万般技术学不透,唯有bug伴终生!