一次线上JVM问题的排查——一把无人持有的锁

背景

近期，闲鱼核心应用出现了一个比较难解决的问题。在该应用集群中，会随机偶现一两个实例，其JVM运行在一个挂起的状态，深入分析stack文件发现，此时jvm中有大量的线程在等待一把没有任何线程持有的锁。问题实例所在的机器负载相对正常机器要轻很多，而其线程数则大幅增多。由于该问题在逻辑上的冲突，加上周边问题的复杂性，使得研究、分析、解决该问题变得相对来说困难与曲折。本文将系统性地介绍如何解决这个问题，并找出问题背后的原因。

问题分析

在实际解决这个问题的时候，我们发现不仅问题本身显得不合常理，其周边环境也相对来说不友善，给问题的分析与解决带来了较大的困难。

• 集群中随机出现。 问题随机出现在该应用集群中的一个或几个实例中，无法提前预知其出现规律。

• 单机出现时间不可预知 ，现场捕捉困难，捕捉风险大，一般发现已经为事后，无现场第一手数据。从单个机器，或者单个实例看，则是出现概率非常低，出现时间完全随机。这使得蹲点单台机器以捕捉这个问题的思路几乎行不通，策略扩大至整个集群又可能出现稳定性及性能问题。

• 问题出现频率低。 出现频率大概在一到两天一次。

• 问题表现复杂。 该问题的表现很复杂，不仅从第一眼看去不合常理，JVM内部出现了大量线程在等待一把没有任何线程持有的锁。另外，问题机器的负载非常低，基本上在5%以内，相当于空载，而JVM中线程数却非常多，最多发现过接近4k个线程。

• 问题周边环境复杂。 该问题出现前后，应用先后引入了rxjava、协程，应用为早期应用，服务结构复杂，而log4j问题又和网上大量的文章情形不符。

• 验证困难。 理论分析完成后，无法在线上复现及验证，安全性、稳定性、数据等都不允许直接在线上验证。

解决方案

解决这个问题的主要按照以下六步，一步步排除法，最终定位并解决问题。按照先易后难，先直接后理论，先数据后源码的顺序，总结出来以下六步，大体上投入时间逐步增加，难度也逐渐增加。

step1. 代码bug查找

代码问题指的是业务代码本身逻辑问题把JVM带入了某种故障状态。问题的分析及排除很简单，通过观察应用日志即可。

step2. 现场捕获

定位了问题，问题也就解决了一半。

step3. io hang

考虑到大部分实例业务日志打印缓慢或者根本不再打印，可能原因是io方面出了问题，通过查看容器硬件监控及应用火焰图，可以轻松将IO问题排除。

step4. 锁分析

锁问题主要包含 死锁 和 丢锁 。 死锁 的特点很明显，一旦发生死锁，则与该锁相关的线程都将停止。首先这点和大量实例运行缓慢不符，其次，这个问题可以轻易通过 stack文件 排除。 丢锁 主要和 协程 有关，和死锁相似，考虑到协程可能在切换过程中发生丢锁，造成的现象和该问题很类似，即没有线程持有的锁。丢锁最主要的问题也是不可恢复，一旦丢锁，则JVM相关线程就永远不可恢复，和该问题不符。另外，观察大部分stack文件发现，此时JVM中的协程数量并不多，线程池Worker实例也在变化。

step5. 资源耗尽查看

资源耗尽是指JVM运行过程中由于部分资源紧张，程序虽然可以正常运行，但是限于部分资源紧张，必须等待其他线程释放了持有资源后，当前线程才可以继续运行。资源包括 软件资源 和 硬件资源 。 软件资源 是指在JVM运行过程中，有设定上限的软件资源，如堆、Reserved Code Cache、元数据区等，在实际观察中，发现上述资源均未出现明显的资源耗尽情况。 硬件资源 主要分析在JVM运行过程中，所在机器硬件资源如CPU、内存、网络等硬件资源使用情况。其中，在观察中发现，内存资源出现了明显的问题，由于问题机器线程数大幅增加，导致问题机器JVM总使用内存超出了机器的物理内存。加上监控进程与机器本身的进程，很容易得出一个结论，JVM此时在将部分资源扇出至page页。实际上，JVM此时在 部分基于硬盘运行 。如果此时JVM进行一个牵涉面很广的抢锁任务，那么就有可能发生悲剧。而在该问题中，应用采用了log4j作为日志记录工具，查看相关源码可以看出，log4j采用了java monitor来控制日志打印，防止日志结构混乱及数据破坏。而作为流量入口日志，所有的业务线程都会进行进行打印，因此也会进行抢锁。

查看HotSpot源码，在退出临界区时，首先要做的是把锁状态重置，也即对象头重置及Montior对象当前owner置NULL，然后才会唤醒所有相关线程抢锁。如果此时内存放不下所有有关线程，随着线程的唤醒，活跃线程会被扇出以提供内存空间。大量的扇入和扇出使得这个过程显得很缓慢，也就出现了一个 没有任何线程持有的锁 ，实际上JVM此时在进行一个艰难的抢锁任务。

step6. 框架层源码阅读

在前面步骤中大致定位了一个大的方向，线程数增加导致内存不足。接下来需要深入框架层去分析 引起线程数增加的可能原因 。先后对HSF、Modulet、Mtop、netty等框架进行了源码级别的分析，主要跟踪各个框架 线程分配策略 。其中，HSF默认设置的线程池模型扰动抗性很低。在HSF框架中，netty线程池将任务提交到HSF Provider线程池，HSF Provider线程池采用业务隔离设计，在一次对外服务中，HSF Provider大量调用HSF Consumer，而Consumer会被提交至Consumer线程池中执行。在该应用中，Provider和Consumer线程池容量比例大于200:1。

而根据业务实际，合理的比例应该在1:1附近。

失衡的线程池结构，极容易服务发生网络抖动、回环调用时使Consumer线程池服务能力下降，进而使整个应用实例对外服务能力下降。而有规律的故障不应该和无规律的抖动有关。

回环与问题出现频率之间读者可以通过概率论进行分析，假定100台机器，则每次请求会有1/100的概率发生回环，同理，每10000次请求就会发生双回环，1M次请求则是3回环。在该问题中，概率论分析和实际情况是契合的。

在研究框架层的时候，发现了回环调用对系统的危害。但是还有一个疑问需要回答， 回环调用完成后，应用应该能恢复 ，而线上实际情况是，自恢复是个小概率事件。结合前一节可以得出一个结论，回环调用使应用Consumer线程池处理能力下降，进而使 上游线程池水位逐渐提升直至被打满 。 而数量过度增加的线程池使得内存资源紧张，导致JVM基于磁盘运行而抢锁困难，抢锁过程的拉长使得 没有任何线程持有锁 这个常规状态下的瞬时状态被拉长，JVM服务能力大打折扣，而duct平台由于策略原因不能应对该问题的特殊情况导致其无法启动切流，流量照常打入JVM。于是就形成了一个恶性循环，线程数提升导致JVM进入一种非常规状态，服务能力下降，而流量照常，导致线程数很难下降。于是，JVM长时间运行在一个非常缓慢的状态，从表现上来看就是 jvm挂起 。下表为一个较有代表性的流量对比（实际上故障机状态跨度非常大，这两台机器 较为典型而已）

实验验证

接下来，本文采用阿里PAS压测平台，对预发机器进行了压测验证。由于线上问题复杂，无法复现线上的环境，只能对其诱因进行验证。下表为压测过程中应用的性能表现。由于压测模式限制，所支持的最大tps在超时的情况下非常低，如表所示只有80左右，考虑到压测环境机器数量，回环数量还要打折。

从下图可以看出，平均RT为2500ms左右，绝大多数请求都在超时状态。

压测结果表明，回环不需要多高的流量，就能把应用实际服务能力大打折扣。考虑到线上还有其他类型的请求，填充在回环之间，这会使线程池迅速打满，并使得 处理回环请求的时间加长 ，恶化应用从回环调用中恢复的能力。

总结和思考

在JVM出现问题的时候，首先要 阅读业务代码 ，这个虽然看似作用不大，却有可能以相当低廉的代价解决问题。之后，主要思路就是 捕获现场 ，现场捕获将极大程度上有助于问题的解决。如果该步骤不可行，或者成本相对较高，可以先去排查周边原因。这主要包括 IO 、 锁 、 硬软件资源 ，在执行这些排查的时候，要留意这些方面出问题的表现和实际问题的表现契合度。比较明显的就是一旦死锁、丢锁，或者IO hang，则程序无法从故障状态恢复，相关线程也不能继续执行。这些特点可以协助排除部分大的方向。最后，对 资源耗尽 的排查，则是基于本文所述问题的一个基本特点，绝大多数JVM运行缓慢而不是停止运行。所以，资源紧张成为一个解决问题的大方向，并最终定位了问题。深入到 框架层 主要是从理论上分析问题产生的原因，然后在结合实际情况，分析整个解决思路的正确性。读者在遇到类似JVM问题时，可参考本文所述的方法与步骤，对实际问题进行分析与研究。

闲鱼技术团队不仅是阿里巴巴集团旗下闲置交易社区的创造者，更是移动与高并发大数据应用新技术的引导者与创新者。我们与 Google Flutter/Dart 小组密切合作，为社区贡献了多个高 star 的项目和大量 PR 。我们正在积极探索深度学习和视觉技术在互动、交易、社区场景的创新应用。闲鱼技术与集团中间件团队共同打造的 FaaS 平台每天支持数以千万级用户的高并发访问场景。  

就是现在！ 客户端／服务端java／架构／前端／质量 工程师 面向社会+校园招聘，base杭州阿里巴巴西溪园区，一起做有创想空间的社区产品、做深度顶级的开源项目，一起拓展技术边界成就极致！

*投喂简历给小闲鱼→ [email protected]

开源项目、峰会直击、关键洞察、深度解读

请认准 闲鱼技术