ARTICLE DETAIL

资讯详情

深耕郑州网站建设与运营推广的一线实战洞察。

Java内存泄漏排查实录:ThreadLocal未清理导致线程池堆积

Java内存泄漏排查实录:ThreadLocal未清理导致线程池堆积 一次内存泄漏问题排查和分析小坑做后端开发这些年内存泄漏这种问题遇到不少但大部分时候是那种一上来就OOM崩溃的大事故好查也好修。真正让人头疼的反而是那种内存悄悄上涨、看起来没毛病、跑个两三天就GG的小坑。最近我就踩了一个这样的坑排查过程倒不算特别曲折但里面有几个点挺典型的写出来给大伙儿做个参考。先交代一下背景一个标准的Java微服务跑在K8s集群里堆内存设了4G用的G1垃圾回收器。某天监控报警说服务的内存使用率持续走高从早上的30%一路爬到晚上90%眼看就要触及容器限额了。但诡异的是CPU和GC都很平稳既没有频繁Full GC也没有大量的GC日志报错就是内存像滴水一样一点一点往上涨。重启之后内存能回落但跑几天又会爬上来典型的缓慢内存泄漏特征。这次排查我踩的坑其实不算特别深但过程挺有代表性从现象定位到堆内存泄漏一步步追到线程池里的ThreadLocal最后发现是一个特别不起眼的业务代码细节。整个过程我可以拆成几个阶段每个阶段都有一些值得记录的细节今天一并说清楚。1. 排查前期的思路先分清“内存涨”和“内存泄漏”很多人一看到内存上涨就急着dump堆这其实是个误区。你要先搞清楚一个问题当前的内存增长到底是不是真的泄漏Java应用的内存占用曲线本来就应该是锯齿状的因为Young GC和Full GC会周期性回收对象。如果你看到的内存曲线是平滑上升、垃圾回收之后也不回落那才叫泄漏。如果曲线是锯齿状但整体水平在缓慢抬高那也有两种情况一种是确实有对象被人为持有另一种是老年代正常晋升但GC的阈值没触发Full GC导致老年代被渐渐填满。我第一步做的就是先看监控曲线确认形态。这台机器的曲线非常典型每天上午10点左右开始爬坡凌晨2点有波谷但波谷的高度一天比一天高。3天之后波谷都比最初的峰值还高。这说明确实有东西没被回收不是自然波动。确认了泄漏方向之后我开始盯着两样东西看堆内存的使用率和GC情况。如果是对象持续增长通常你会看到Young GC频率越来越高、单次GC后存活对象越来越多、或者Old Gen持续膨胀。我看了一下GC曲线发现一个问题Young GC频率其实没有明显变化但每次GC之后存活下来的对象比例在变大Old Gen的占用从开始的1.2G一路涨到2.8G。这个信息很重要它说明有对象从新生代晋升到了老年代而且一旦到了老年代就再也没被回收过。提示排查内存泄漏第一步永远是“看一眼内存曲线和GC曲线”别急着dump。曲线本身就能告诉你大量的信息能少走很多弯路。2. 抓现场用jstat和jmap锁定泄漏方向确认了堆内存在持续膨胀之后第二步就是抓现场。所谓抓现场就是拿到一个“能说明问题”的堆快照。这里面有个细节dump的时机非常关键。我犯过的一个小错误是第一次dump之前没有做任何处理结果dump出来的文件里全是正常业务对象根本分辨不出谁在泄漏。后来我学乖了先把应用跑上一个小时确认内存曲线还在爬坡然后手动触发一次Full GC用jcmd或者jmap -histo先触发一次GC等曲线降下来之后再记录一个“基线”然后再跑一段时间观察哪些对象在持续增长。具体来说我的操作顺序是这样的用jstat -gcutil pid 1000看实时GC情况确认老年代使用率在持续上涨用jmap -histo:live pid触发一次Full GC并打印存活对象直方图记录下来过5分钟再执行一次同样的命令对比两次直方图里哪些类的实例数在增长找出增长最明显的那个类再用jcmd pid GC.heap_dump /tmp/heap.hprof生成堆快照用MAT分析。第一次jmap -histo:live出来的时候我看到最前面的都是些正常的业务对象、byte数组和String这些没啥参考价值因为一个大对象会拆成很多数组。第二次对比时我注意到一个名叫com.xxx.wrapper.UserContext的实例数从几百涨到了几千而且每个实例内部都带着一大坨Map结构。直觉告诉我疑点就在这个类身上。这里插一句很多人惯用的jmap -dump:live其实有个隐藏风险它会先触发Full GC在流量高峰期这么做容易造成业务停顿。我当时用的是jcmd的GC.heap_dump它默认不触发GCdump出来的文件更接近当前真实状态对比分析起来更准。注意用jmap -histo:live排查对象增长虽然好用但它会触发Full GC线上操作要挑低峰期或者干脆分两次执行、中间留出足够时间别在高峰硬刚。3. MAT分析顺着引用链找到“钉子户”拿到heap dump之后我用的工具是Eclipse MAT。这个工具在排查内存泄漏方面真的YYDS尤其是它的Leak Suspects报告能直接帮你圈出嫌疑对象。我打开hprof文件2.1G花了一两分钟还能接受第一时间看的就是Leak Suspects。报告里给出了几个“可疑点”第一个就直接指向了java.lang.Thread内部持有的ThreadLocal.ThreadLocalMap里面挂着大量的UserContext对象。看到“ThreadLocalMap”这几个字我心里就有数了——典型的ThreadLocal用法不当。但光知道是ThreadLocal还不够你得搞清楚是谁往里塞东西、什么时候塞的、为什么没清。我用MAT的Open Query Browser Paths to GC Roots从UserContext实例出发一步一步往上找引用链。链路大概是这样的UserContext - ThreadLocal.ThreadLocalMap.Entry - ThreadLocal.ThreadLocalMap - Thread在MAT的Dominator Tree里我能看到某个线程下面挂着几百个Entry每个Entry的value都是一个新的UserContext实例。换句话说这个线程处理过的每一次请求都往它自己的ThreadLocalMap里塞了一个对象而因为线程池里的线程是长期存活的这些对象就永远被线程对象强引用着GC一直回收不掉。这里有个很微妙的点一般ThreadLocal的key是WeakReference所以如果ThreadLocal对象本身没被强引用key会被回收、value也能跟着被清掉。但这个案例里key是某个静态工具类里的静态ThreadLocalUserContext变量它是强引用永远不会被回收所以每个Entry都活得好好的value只会增加不会减少。这就是这个坑的“小”所在——代码看着完全没问题一个静态变量、一个set、一个get谁能想到会漏呢。再看堆里的对象分布UserContext内部挂着一个HashMap里面装着用户信息、登录态、请求参数一个对象撑个几KB到几十KB不等。单个对象倒不大问题是线程池有20个线程每个线程每天要处理上万个请求两天下来就是几十万个对象被强引用堆内存不涨才怪。4. 层层深入到修复问题出在过滤器里顺着引用链往下追我找到了泄漏的源头——一个基于OncePerRequestFilter的过滤器它做了这么个事情Component public class UserContextFilter extends OncePerRequestFilter { Override protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException { // 从请求头/Token解析出用户信息塞到ThreadLocal里 UserContext context parseUser(request); UserContextHolder.set(context); // 问题就出在这里没有在finally里做清理 try { filterChain.doFilter(request, response); } finally { // 某些情况下这里不会执行到或者根本没写这一步 } } }UserContextHolder的实现也很简单public class UserContextHolder { private static final ThreadLocalUserContext CONTEXT new ThreadLocal(); public static void set(UserContext ctx) { CONTEXT.set(ctx); } public static UserContext get() { return CONTEXT.get(); } public static void remove() { CONTEXT.remove(); } }你发现问题了没set()之后过滤器的finally块里压根儿没调用remove()。在普通的同步请求里问题不大因为请求走完线程就归还线程池ThreadLocalMap还留在Thread上但下一个请求复用这个线程时会再次 set覆盖掉旧值所以一个线程最多挂一个实例看起来不严重。但这个服务有个特殊的业务路径请求在过滤器中解析完用户信息之后会异步提交到另一个自定义线程池去处理也就是说过滤器所在的Tomcat线程并没有执行完整流程就返回了而真正干活的是业务线程池里的常驻线程。这就要命了。因为在异步线程池里执行任务时代码里也调用了UserContextHolder.get()去取用户信息也就是说异步任务的执行线程业务线程池里的线程也会被 set 一次UserContext但异步任务的结尾同样没有调用remove()。而且一个业务线程会处理成千上万个任务每次set进去的都是一个新对象这个线程的ThreadLocalMap就会疯狂膨胀。排查到这一步我基本上已经能确认完整的泄漏链路了请求进来过滤器解析用户上下文set到线程池A的线程上异步任务被提交到线程池B线程B执行任务时从ThreadLocal里get到上下文经过业务处理又set了新的上下文线程B是常驻线程处理完任务后被归还给线程池但ThreadLocalMap上的entry没有被清理下一个任务复用线程B重新set一个对象覆盖到map里但之前set进去的对象并没有被覆盖掉因为ThreadLocalMap的entry是以key为索引的同一个key的set操作会覆盖value注意这里会被覆盖但那些在业务执行过程中new出来并塞进同一个key的对象如果当时没remove旧值就被新值覆盖了理论上不会膨胀才对。等等这里我总结的时候才发现如果只是同一个ThreadLocal key反复set旧value会被新value覆盖为什么实例数还在涨我回头仔细翻了MAT的对象分布发现更精确的现象膨胀的并不是同一个ThreadLocal key下的 entry而是每次异步任务都创建了新的 ThreadLocal 对象比如业务代码里某个工具类自己定义了ThreadLocalUserContext然后set进去但没remove。这种情况下每次set都是一个新的keyEntry就增多了。找到这个工具类之后事情就更加清楚了public class TaskContext { // 这里定义了一个非静态内部类的ThreadLocal实例 // 或者每次创建了一个新的ThreadLocal对象 private final ThreadLocalMapString, String localMap new ThreadLocal(); public void run() { localMap.set(new HashMap()); // ... 业务逻辑 // 没有remove() } }如果TaskContext是被每个任务new出来的那么localMap就是一个新的ThreadLocal每次set都会往线程池线程的ThreadLocalMap里新增一个Entry。于是每处理一个任务线程的ThreadLocalMap就多一个条目。业务线程池里有几十个线程每个线程处理几万个任务那就是几十万个Entry每个Entry里还带着一个永远不会被回收的HashMap。最终修复方案其实很简单在异步任务执行完毕之后显式调用localMap.remove()或者在finally块里清理。我给这个工具类加了finally清理逻辑同时给过滤器也补上了finally { UserContextHolder.remove(); }双保险。修复之后的验证也很直接重启服务观察两天内存曲线稳定在30%左右调峰也有但整体不再爬坡老年代占用稳定问题解决。5. 复盘这次“小坑”背后的三个技术细节排查完之后我坐那儿仔细想了想这个坑为什么会这么隐蔽有三点值得展开聊一聊。5.1 ThreadLocal的弱引用和强引用容易混淆很多人有个误解说ThreadLocal的key是WeakReference所以ThreadLocal理论上不会泄漏。这个说法不够准确。弱引用只保证“ThreadLocal对象自身”可以被回收但value是强引用如果key对应的ThreadLocal被回收了value还在等到下一次set或get时才会把key为null的entry清理掉ThreadLocalMap的expungeStaleEntry机制。但这个机制有个前提你得继续对这个ThreadLocalMap进行get/set操作。如果这个线程后面再也不访问这个ThreadLocal了那些value会一直挂在Thread上直到线程销毁。如果线程是线程池里的常驻线程那基本等于永久泄漏。所以ThreadLocal的正确用法就一句话凡是set过的地方不管正常返回还是异常抛出都要remove。5.2 线程池复用放大了泄漏如果这个功能用的是普通的HTTP请求线程请求结束、线程回收ThreadLocalMap也会被回收泄漏根本没有放大机会。但问题是异步线程池的线程是常驻的一次泄漏会在同一个线程内反复累计。例子一个线程处理5000个任务每个任务往ThreadLocalMap里塞一个对象这个线程就会多挂5000个对象20个线程就是10万个。摊上大对象内存直接就顶不住了。所以排查方向很大程度上取决于你应用的并发模型如果服务大量使用线程池、异步任务、xxl-job这种调度组件那ThreadLocal水平泄漏的概率极高。5.3 为什么复现难、前期测不出来这个坑最坑爹的地方在于本地跑、单测、低并发预发环境全都看不出问题。只有并发量上去了、线程池循环使用到一定次数之后内存才会肉眼可见地涨。因为单测时一个线程通常只处理一个任务线程就结束了ThreadLocalMap跟着线程一起销毁自然没泄漏。等你上了高并发问题才浮出来。这也解释了为什么线上问题往往比测试环境高一到两个档次。测试环境没有足够大的线程复用压力很多类似的“静态状态污染”问题都会被掩盖。6. 常见问题和排查技巧实录下面整理几个这次排查过程中问过自己、也经常被同事问到的问题算是速查表性质的东西。6.1 内存泄漏和内存溢出是一回事吗不是。内存泄漏是“该回收的对象没被回收”内存还在慢慢被占内存溢出是“内存确实不够用直接抛OutOfMemoryError”。内存泄漏积累到一定程度会引发溢出但反过来溢出还有一种情况是某个瞬间峰值过大比如一个大批量查询跟泄漏无关。排查时先看曲线平滑爬坡、不回落基本就是泄漏尖峰冲高、GC之后恢复那就是瞬时压力问题。6.2 dump文件太大MAT打不开怎么办heap dump动辄好几个GMAT默认给的内存不够会直接报An unexpected error occurred。我给个经验值-Xmx给到dump文件大小的1.2到1.5倍比如6G的dumpMAT启动参数改成-Xmx8192m。修改方式是改MemoryAnalyzer.ini在文件尾部加一行-Xmx8192m。要是还不行那就别加载全部对象了先用jmap -histo:live拿到对象直方图粗筛一次或者用MAT的OQL直接跑查询只提取你关心的类路径省的把整个堆都load进内存。6.3 jmap执行时线上服务卡顿了怎么办jmap -histo:live和jmap -dump:live都会触发Full GC如果线上是高峰期轻则GC耗时长、重则接口超时。更安全的做法是先用jstat -gcutil确认当前GC状态正常再选低峰期执行用jcmd pid GC.heap_dump代替jmap -dump:live它不强制Full GC如果必须抓现场按顺序一次histo、间隔五分钟、一次dump中间别做其他操作。6.4 排查时发现好几种对象都在涨怎么快速缩小范围我的做法是拍两轮“对比快照”。先记录此时哪些类实例数最多过十分钟或半小时再记录一次把两次直方图做差涨得最快的那个类往往是泄漏点。具体可以配合jmap -histo:live | sort输出排序结果或者写个简短的shell脚本做diff。这个办法比直接拿MAT分析大海捞针高效得多。6.5 有没有别的容易漏掉的“小坑”可以提前防结合我个人的经验除了ThreadLocal不remove之外还有几个高频小坑也容易造成缓慢内存泄漏静态集合当缓存用static Map里 put 了数据就没人清理key还得看情况value永远被强引用Socket/IO流没关连接池里的空闲连接、未释放的流积累起来也很要命事件监听器没反注册像Spring的ApplicationListener每次操作往里add一个从不remove第三方库的内部缓存比如某些HTTP客户端、RPC框架会缓存路由表、类信息、响应数据你得查它们的缓存配置和过期策略。这类问题共性很突出代码里每一处小疏忽在长期运行和高并发下都会被无限放大。排查这类问题靠的是一个系统性的认知和工具链而不是碰运气。这次打完收工之后我给团队立了个小规矩所有用ThreadLocal的代码Code Review时重点看有没有在finally里remove所有新增的异步任务统一要求自定义线程池并且在线程池的名字里带上业务标识方便排查堆栈时一眼定位。以后再遇到内存曲线偷偷爬坡的问题至少能少走两小时弯路。
返回列表