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

1 背景

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

2 问题分析

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

• 集群中随机出现。问题随机出现在该应用集群中的一个或几个实例中，无法提前预知其出现规律。
• 单机出现时间不可预知，现场捕捉困难，捕捉风险大，一般发现已经为事后，无现场第一手数据。上述问题换个角度看，从单个机器，或者单个实例看，则是出现概率非常低，出现时间完全随机。这使得蹲点单台机器以捕捉这个问题的思路几乎行不通，策略扩大至整个集群又可能出现稳定性及性能问题。
• 问题出现频率低。出现频率大概在一到两天一次。
• 复现困难。无法在生产环境直接对分析结果进行复现验证。
• 问题表现复杂。该问题的表现很复杂，不仅从第一眼看去不合常理，JVM内部出现了大量线程在等待一把没有任何线程持有的锁。另外，问题机器的负载非常低，基本上在5%以内，相当与空载，而JVM中线程数却非常多，最多发现过接近4k个线程。
• 问题周边环境复杂。在问题出现前后，该应用部分提供的服务引入了rxjava，rxjava本身在运行过程中会大量创建线程。该应用基于阿里JDK，采用了协程机制，stack文件显示问题机器最多的栈是协程对应的栈。问题实例中大多数的锁和log4j相关，而网上大量的针对log4j使JVM挂起的情形又和该问题的表现不符。另外，该应用历史悠久，作为闲鱼早期的核心应用，服务结构复杂，不仅有针对前端的http服务，还有面向底层的基础服务，服务跨层现象明显。
• 验证困难。理论分析完成后，无法在线上验证，安全性、稳定性、数据等都不允许直接在线上验证。

3 问题解决方案

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

3.1 代码bug查找

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

3.2 现场捕获

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

一般来说，定位问题主要有两个分类，即时定位，事后定位。前一种是指我们实时直接监控JVM信息，在关键信息异常时，即发生动作。配合周期性的信息采集，基本可以对问题发生时刻前后数据精准采集和对比。做法一般是采用JVM代理方式或JMS方式。JVM代理分为C语言和Java语言代理，C语言代理运行在JVM层，可以做到即时Java代码发生故障故障，依然可以正常采集信息。Java代理相对C语言代理来说编写起来方便，实际上C语言部分任务还是通过JNI接口构造Java对象执行的。JMS方式可以实时采集各种指标，也是目前监控主要采用等方式。缺点是对应用的侵入性非常大，不适合解决问题用。事后定位是指通过日志监控等较缓慢的方式去对问题发生时刻定位，由于该问题的特殊性，日志无法提供需要的信息以判断故障，另外，日志无法采集我们需要的信息，尤其是JVM内部线程和锁的信息。
在后续现象的观察中，发现了一个比较普遍的现象，应用由正常转为故障需要一个漫长的时间，应用可能在临界区停留相当长的时间，极端例子中应用在线程数提升后依然能够正常运行接近24小时，之后发生了自恢复。另外，在和JVM组同学对接的时候，又被告知阿里jdk对C代理支持可能由于安全原因被关闭。基本上宣布这个问题的研究进入了下一个阶段。

3.3 io hang

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

3.4 锁分析

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

3.5 资源耗尽查看

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

public void callAppenders(LoggingEvent event) {
    int writes = 0;

    for (Category c = this; c != null; c = c.parent) {
        // Protected against simultaneous call to addAppender, removeAppender,...
        synchronized (c) {
            if (c.aai != null) {
                writes += c.aai.appendLoopOnAppenders(event);
            }
            if (!c.additive) {
                break;
            }
        }
    }

    if (writes == 0) {
        repository.emitNoAppenderWarning(this);
    }
}

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

for (p = w ; p != NULL ; p = p->_next) {
    guarantee (p->TState == ObjectWaiter::TS_CXQ, "Invariant") ;
    p->TState = ObjectWaiter::TS_ENTER ;
    p->_prev = q ;
    q = p ;
}

// Prepend the RATs to the EntryList
if (_EntryList != NULL) {
    q->_next = _EntryList ;
    _EntryList->_prev = q ;
}

3.6 框架层源码阅读

在前面步骤中大致定位了一个大的方向，线程数增加导致内存不足。接下来需要深入框架层去分析引起线程数增加的可能原因。
先后对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挂起。
下表为一个较有代表性的流量对比（实际上故障机状态跨度非常大，这两台机器较为典型而已）

4 实验验证

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

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

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

5 总结

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