性能文章>一次资源泄露问题排查纪录>

一次资源泄露问题排查纪录原创

726319

问题背景

前不久技术学院负责人让我帮助维护下⼤讲堂、积分管理等⼏个系统。这些系统功能都已经很稳定,也不会再有新的功能开发,但是⼤讲堂系统自上线后,每过⼀段时间就会出错,导致学员⽆法报名课程,希望我帮助解决下。这种累积下来的问题解决起来⽐较难,但是对能⼒提升帮助很大,我欣然接受了,所以就有了这次“艰苦”的问题排查和解决之旅。

解决思路

本人未参加过大讲堂和积分系统的开发,解决问题⾸先要最⼤化的了解系统背景、问题发⽣时的系统表现等信息。技术学院的同事和我说,负责系统的开发⼈员已经换过⼏波了,现在基本已经找不到了解系统的开发⼈员了,但是也反馈了以下信息:
1、系统是16年公司应届⽣培训时做的项⽬。
2、其他系统运⾏良好,就是⼤讲堂系统偶尔会报错,导致学员⽆法报名,重启下就好了,果然是“重启⼤法”好啊。
3、系统出错的频率不⾼,但是貌似很有规律,⼤半个⽉左右出现⼀次。
根据以上描述,特别是出错后“重启⼤法”特别有效,出错频率基本固定,通过这两点基本上可以断定是资源泄露导致的问题。既然确定是资源泄露问题,对于 Java 应⽤来说排查⽅向也就确定为以下2个⽅向:
1、对象泄露
2、线程泄露
3. 处理过程
前文提过本人并未参与项目开发,所以整个排查大部分是通过 linux 和 jvm 的⼀些命令行辅助功能来进行的,下面是整个排查过程:
1、 首先通过 jps 确定 Java 应用的进程 id

sudo -u tomcat jps -lv | grep qtscore

image.png

2、 排查内存泄露

通过持续观察 GC 日志文件 /home/q/www/qtscore/log/gc.log 文件,发现 GC 执行频率正常,特别是 Full GC 执行也并不频繁,虽然内存使用量在持续增长,但是并不明显。

为了确认业务代码是否存在泄漏,通过 jmap 查看了堆内对象分布情况,切记此命令会导致进程暂停,如果是 qps 高或者响应时间要求高的应用慎用:

sudo -u tomcat jmap –F -histo 11035

image.png

存泄露的可能性。
3、 排查线程泄露

top -H -p 11035

image.png

通过结果可以看出线程已经高达4038,应用中dubbo线程池默认配置是200个线程,tomcat线程池配置也是200个线程,所以这个线程数明显不合理。参照另外一个同等应用,其线程数未超过500,所以可以初步判断系统存在线程泄露,下⼀步只能查看线程栈信息了:

sudo -u tomcat jstack -l 11035 > /tmp/qtscore_stack.log

image.png

系统中存在100多个“New I/O boss"线程,这个应该是 netty 线程池的 boss 线程,到这里基本上可以确认是线程池泄露引起的问题了,但是究竟是哪段代码引起的,线程栈中并无业务相关代码,只是 netty 线程池的代码,所以无法判断出引起问题的代码源头,只能先看看系统日志中是否有价值的信息了,发现系统日志中频繁报以下错误:

image.png

找到对应的源代码进行查看,发现这是⼀个 dubbo 服务接口,而 dubbo 底层用的就是 netty,种种迹象表明问题应该就出在这里。仔细分析代码后,发现这个 dubbo 接口抛出的异常 QtalkQueryException,居然没有通过 api 暴露给调用方,也就是说调用方是无法正确反序列化这个异常的。初步推测可能就是这个原因导致 dubbo 未能正确处理线程池,导致线程池泄露了。将 QtalkQueryException 改为抛出 IllegalStateException 异常,发布上线,满怀期待地等着问题被完美解决。过了一个星期后,通过 top 命令查看进程的线程数,发现线程数又飙升到1千1百多了,看来问题还是没有解决,只能再排查了,但是基本上可以确定是线程泄露问题,而且是 netty 引起的,可是线程栈中 netty 的 worker 线程栈中没有任何业务相关的代码,应该是代码间接用到了 netty 线程池,但是一时没有了头绪。只有找同事咨询一下了,和几个同事讨论后,大家都认为最有可能用到线程池的就是异步请求,特别是一些HTTP客户端,根据这个思路对代码进行排查后,发现系统中有如下代码:

image.png

这个 com.ning.http.client.AsyncHttpClient 底层用到了 netty 线程池,这个用法存在明显错误,AsyncHttpClient 实例应该重用,而不应该每次使用时都创建一个。修改代码后重新发布上线,一周后再统计应用线程数,发现线程数稳定在350个左右,确认问题得到了解决。但是故事还没有结束,个人觉得既然应用报错,日志应该有所体现才对,难道是被其他异常淹没了?所以重新排查了出错日期的日志,果然发现了以下错误信息:

image.png

通过系统命令 ulimit –a 发现系统最大用户线程数是4096,所以问题是创建的线程超过了系统最大用户线程数限制。

image.png

经验总结

回顾这次问题排查经历,其实这个问题排查起来并不难,最初的排查方向也是对的,但是整个过程还是花费了很长时间。回顾整个过程,总结出以下经验和教训:

  • 大规模使用的基础组件(例如:Dubbo)不容易有问题,即使有问题也会被及时修复,所以还是要多分析自己编写的代码。

  • 排查问题首先要仔细分析系统日志,报错的地方⼀般也就是引起问题的源头,遵循和重视这个原则,通常可以大大提高排查问题的效率。

本文来自:Qunar技术沙龙,作者:王彦军

请先登录,再评论

估计上手前先撸一遍日志,找到任何exception,error

1年前

为你推荐

关于内存溢出,咱再聊点有意思的?
概述 上篇文章讲了JVM在GC上的一个设计缺陷,揪出一个导致GC慢慢变长的JVM设计缺陷,可能有不少人还是没怎么看明白的,今天准备讲的大家应该都很容易看明白 本文其实很犹豫写不写,因为感觉没有
字符串字面量长度是有限制的
前言 偶然在一次单元测试中写了一个非常长的字符串字面量。 正文 在一次单元测试中,我写了一个很长的字符串字面量,大概10万个字符左右,编译时,编译器给出了异常告警 `java: constant
多次字符串相加一定要用StringBuilder而不用-吗?
今天在写一个读取Java class File并进行分析的Demo时,偶然发现了下面这个场景(基于oracle jdk 1.8.0_144): ``` package test; public c
如何通过反射获得方法的真实参数名(以及扩展研究)
前段时间,在做一个小的工程时,遇到了需要通过反射获得方法真实参数名的场景,在这里我遇到了一些小小的问题,后来在部门老大的指导下,我解决了这个问题。通过解决这个问题,附带着我了解到了很多新的知识,我觉得
谨防JDK8重复类定义造成的内存泄漏
概述 如今JDK8成了主流,大家都紧锣密鼓地进行着升级,享受着JDK8带来的各种便利,然而有时候升级并没有那么顺利?比如说今天要说的这个问题。我们都知道JDK8在内存模型上最大的改变是,放弃了Perm
高吞吐、低延迟 Java 应用的 GC 优化实践
本篇原文作者是 LinkedIn 的 Swapnil Ghike,这篇文章讲述了 LinkedIn 的 Feed 产品的 GC 优化过程,虽然文章写作于 April 8, 2014,但其中的很多内容和
「每日五分钟,玩转 JVM」:久识你名,初居我心
聊聊 JVMJVM,一个熟悉又陌生的名词,从认识Java的第一天起,我们就会听到这个名字,在参加工作的前一两年,面试的时候还会经常被问到JDK,JRE,JVM这三者的区别。JVM可以说和我们是老朋友了
JVM垃圾回收与一次线上内存泄露问题分析和解决过程
本文转载自:花椒技术微信公众号 前言内存泄漏(Memory Leak)是指程序中己动态分配的堆内存由于某种原因程序未释放或无法释放,造成系统内存的浪费,导致程序运行速度减慢甚至系统崩溃等严重后果。Ja