原创:扣钉日记(微信公众号ID:codelogs),欢迎分享,非公众号转载保留此声明。
简介
在之前的OOM问题复盘之后,本周,又一Java服务出现了内存问题,这次问题不严重,只会触发堆内存占用高报警,没有触发OOM,但好在之前的复盘中总结了dump脚本,会在堆占用高时自动执行jstack与jmap,使得我们成功保留了问题现场。
查看堆占用分布
发现有heapdump文件后,我立马拷贝到本机,并使用MAT分析,如下:
很显然,好像是什么接口分配了非常大的String对象,一个String对象约200MB,那它是哪分配的呢?
查找大对象分配线程
这个分配行为肯定是某个线程做的,而线程是最常见的GC Root,因此只要查找对象的GC Root即可,如下:
找到了大对象对应的分配线程是http-nio-8088-exec-6,如下:
查看线程栈
如何查看这个线程在干什么呢?在MAT中摸索了一会,没找到相关内容,回想起我们的dump脚本中记录了jstack,打开看看,如下:
可以发现,这个线程正在做json序列化,但我仔细找了好一会,也没有找到相关接口的Controller,这是因为线程已经执行完了Controller里面的逻辑,之后返回接口响应数据时分配的大对象。
可是,线程栈中没有业务代码,就没法定位是哪个接口有问题了。。。
检查accesslog日志
考虑到分配大对象的接口肯定会很慢,于是我转向查看tomcat的accesslog日志,如下:
终于,找到了问题接口,这个接口是用来查询商品数据的,当输入3时会查询出所有3开头的商品,而这有20w+数据,解决问题很简单,加个limit完事。
排查过程复盘
然而,我一直有个习惯,就是解决一个问题后,我会反思一下问题解决过程中有多少运气成分。
如果你经常阅读排查问题类的技术文章,就会发现不少文章,中间突然有一步定位到了问题根因,可能是突然发现了一个线索,或是硬看代码看出来的,或是猜测某处有问题,我觉得这种排查过程都有不少运气成分,我希望问题是通过多年理论基础的积累和对诊断工具的熟练使用,而有章法的一步步查出来的。
而上面通过accesslog能够定位到问题,有一定的运气成分,因为本次内存问题不极端,如果此接口请求量大,那就会瞬间触发多次FGC,进而会影响其它接口也变慢,进而无法分辨出哪个是导致问题的接口!
我想,从理论上来说,Java堆文件里面,应该有线程栈以及线程栈上的参数,因为线程是对象,参数也是对象,它们理应都在堆里,于是我找了个空闲时间,又摸索起MAT这个工具了。
MAT查看线程栈
摸索了一会,我就发现有这样一个按钮,可以查看线程信息,如下:
找到前面说的线程http-nio-8088-exec-6,展开后,就可以发现线程栈以及栈上的参数,如下:
这就找到了请求的Request参数对象,再将Request对象多次展开后,就可以找到接口url信息,如下:
嗯,这样分析heapdump文件真tm的高效啊