当前位置: 首页 > 科技观察

小心踩雷,一场Java内存泄漏排查实战

时间:2023-03-16 14:14:59 科技观察

前几天,团队安排值班轮流照顾我们的服务,主要是做一些告警邮件处理,Bug排查,运行issue处理。工作日还好,不管做什么,都得上班。如果是周末,那么这一天就毁了。不知道是因为公司网络不够广,还是网络运维团队不够强大。网络总是有问题。要么是这里的交换机断网,要么是那边的路由器坏了,偶尔会出现各种超时。我们灵敏的服务检测服务总能准确捕捉到偶尔出现的小问题,为精彩的作品增添一些情趣。好几次,值班组的成员一起吐槽,商量如何避开服务保活机制,偷偷停止检测服务不被发现(虽然不敢)。前几天周末处理一个检测服务锅。问题是晚上7点以后开始的,开始不停的收到报警邮件。电子邮件显示检测到的几个接口已超时。大多数执行堆栈位于:java.io.BufferedReader.readLine(BufferedReader.java:371)java.io.BufferedReader.readLine(BufferReader.java:389)java_io_BufferedReader$readLine.call(UnknownSource)com.domain.detect.http。HttpClient.getResponse(HttpClient.groovy:122)com.domain.detect.http.HttpClient.this$2$getResponse(HttpClient.groovy)我在这个线程堆栈中看到了很多错误。我们设置的HTTPDNS超时是1s,connect超时是2s,read超时是3s。这种错误是因为检测服务正常发送HTTP请求,服务器收到请求后正常响应并正常处理,但是数据包在网络层转发中丢失,所以请求线程的执行栈会停留在接口response的地方。这种情况的一个典型特征是可以在服务器上找到相应的日志记录。并且日志将显示服务器响应非常好。与之相对的是,线程栈停留在Socketconnect处,连接建立时就失败了,服务端完全没有察觉。我注意到其中一个接口更频繁地报告错误。该接口需要向服务器上传一个4M的文件,经过一系列业务逻辑处理后返回2M的文本数据。其他接口是简单的业务逻辑。我猜测可能是上传下载的数据太多了,所以超时导致丢包的概率也比较大。据此推测,该团伙??登录服务器,使用请求的request_id在最近的服务日志中查找。不出所料,由于网络丢包导致接口超时。这样领导当然不会满意,这个结论还得有人接手。于是赶紧联系运维和网络团队,确认了当时的网络状况。网络组同学回复说我们检测服务所在机房的交换机比较老旧,存在未知的转发瓶颈,正在优化中。问题爆发的时候,本以为这个班次会有这么小的波澜,没想到晚上八点多,各个接口的告警邮件蜂拥而至,准备收拾行李的我猝不及防周日休息的事情。这次几乎所有的接口都超时了,而我们这个网络I/O量大的接口每次检测都要超时。难道是整个机房都出了问题?再次通过服务器和监控看到各个接口的指标都很高。很正常,自己测试了一下,界面完全没问题。由于不影响在线服务,我打算先通过检测服务的接口停止检测任务,再慢慢查看。结果我向接口发送了暂停检测任务的请求,很久没有响应。我这才知道,事情并没有那么简单。为了解决内存泄漏的问题,我赶紧登录了检测服务器。首先,我连续做了3次topfreedf。我发现了一些异常:我们检测进程的CPU占用率非常高,达到了900%。我们的Java进程不会做大量的CPU操作。正常情况下,CPU占用率应该在100%到200%之间。如果这个CPU飙升,要么进入了死循环,要么就是在做大量的GC。使用jstat-gcpid[interval]命令查看Java进程的GC状态。果然,FULLGC已经达到了每秒一次:这么多次FULLGC,应该是内存泄漏没有运行,所以使用jstackpid>jstack.log来保存线程栈的场景。使用jmap-dump:format=b,file=heap.logpid保存heap站点,然后重启检测服务,报警邮件终于停了。jstatjstat是一个非常强大的JVM监控工具。一般用法为:jstat[-options]pidinterval其支持的查看项有:class查看类加载信息。compile编译统计。gc垃圾收集信息。gcXXX每个区域的GC详细信息,例如-gcold。使用它对于定位JVM内存问题很有帮助。排查问题虽然问题已经解决,但是为了防止问题再次发生,还是要找出根本原因。栈的分析栈的分析很简单。查看线程数是否太多。大多数栈在做什么:>grep'java.lang.Thread.State'jstack.log|wc-l>464只有400多个线程,无一例外:>grep-A1'java.lang.Thread.State'jstack.log|grep-v'java.lang.Thread.State'|sort|uniq-c|sort-n10atjava.lang.Class.forName0(NativeMethod)10atjava.lang.Object.wait(NativeMethod)16atjava.lang.ClassLoader。loadClass(ClassLoader.java:404)44atsun.nio.ch.EPollArrayWrapper.epollWait(NativeMethod)344atsun.misc.Unsafe.park(NativeMethod)线程状态好像没有异常,再分析一下堆文件。下载堆转储文件。堆文件都是二进制数据,在命令行查看非常麻烦。Java提供的工具都是可视化的,在linux服务器上是看不到的,所以要先把文件下载到本地。由于我们设置的堆内存是4G,dump出来的堆文件也很大,下载起来确实很麻烦,不过我们可以先压缩一下。gzip是一个非常强大的压缩命令,尤其是我们可以设置-1~-9来指定它的压缩级别。数据越大,压缩比越大,需要的时间也越长。推荐使用-6~7,-9太慢了,好处不大。使用此压缩时间,将下载额外的文件。使用MAT分析jvmheapMAT是分析Java堆内存的强大工具。用它打开我们的堆文件(将文件后缀改为.hprof),它会提示我们分析的类型。对于本次分析,果断选择内存泄漏嫌疑人:从上面的饼图可以看出,大部分堆内存都被同一块内存占用,再查看堆内存的细节,向上层追溯,很快就找到了罪魁祸首。分析代码找到内存泄漏的对象,在项目中全局查找对象名,是一个Bean对象,然后定位到它的一个Map类型的属性。这个Map使用ArrayList按照类型存储各个检测接口的响应结果,每次检测完成后塞入ArrayList中进行分析。由于Bean对象不会被回收,也没有这个属性的清零逻辑,所以当服务十多天没有重启时,Map会越来越大,直到内存满。内存满后,无法再为HTTP响应结果分配内存,所以一直卡在readLine。而我们这个I/O比较多的接口,告警次数特别多,估计跟响应大需要更多的内存有关。向代码所有者提了一个PR,问题得到了圆满解决。总结其实还是要反省自己。一开始在报警邮件中有这样一个线程栈:groovy.json.internal.JsonParserCharArray.decodeValueInternal(JsonParserCharArray.java:166)groovy.json.internal.JsonParserCharArray.decodeJsonObject(JsonParserCharArray.java:132)groovy.json.internal.JsonParserCharArray.decodeValueInternal(JsonParserCharArray.java:186)groovy.json.internal.JsonParserCharArray.decodeJsonObject(JsonParserCharArray.java:132)groovy.json.internal.JsonParserCharArray.decodeValueInternal(JsonParser1CharArray.java:)看到了这种错误线程堆栈但没有仔细考虑。要知道TCP可以保证报文的完整性,直到收到报文才会给变量赋值。这显然是一个内部错误。如果您注意并仔细检查,您可以提前发现问题。