一次线上 xxl-job 服务异常排查分析

问题描述

某天收到频繁的告警邮件，定时任务调度失败，查看 xxl-job 的执行器列表是空的，但是服务又显示健康，查看历史任务执行记录发现执行器是依次递减，由于是线上服务，只能先重启，然后线程日志也没有，同时尝试访问服务的健康检查接口，发现健康检查接口访问不通，应该是服务已经挂了，但是因为服务配置的是 TCP 健康检查，握手其实没问题，所以没有检测出来服务异常（血淋淋的教训）。

告警邮件如下所示：

调度日志如下所示：

总结问题现象：xxl-job 的执行器列表为空，TCP 检测正常，服务显示正常，但是 http 健康检查接口访问不了，服务其实处于挂掉状态。

第一次冲锋：初步排查

查看线上的 APM，发现两个异常，

堆内存会定期处于打满的状态（被打满的都是 Eden Space----校长的定时任务计算任务很大，打满也是正常的，而且看了 GC 次数，young GC 和 old GC 也没有太大异常）-----挂掉的时刻和正常情况的堆内存几乎是相同的规律，dump 出线上的内存后，查看也没有什么问题，暂时排除是内存问题导致。堆内存变化如下图所示：

发现重启的服务线程池一直在缓慢的增长，不是很理解，正常的线程池不会一直处于增长的状态，而且增长的数量也很大，线程数量变化如下所示。

进入终端，用 arthas 查看服务器线程状态

arthas 进入终端，执行 thread 命令。确实发现很多的线程处于 WATING 状态，dump 出线程堆栈，发现有 200 多个线程处于 WATING 状态。

arthas 输出结果如下：

fasthread 输出结果如下所示：

arthas 查看 WATING 状态的线程堆栈

arthas 查看 WATING 状态的线程堆栈, 发现所有线程都处于下面的堆栈，看不出什么太多的线索，代码中查看是不是有什么地方设置了无限线程的线程池，发现也没有这么挫的操作。

这些线程到底是谁创建的

张师傅注入线程的 init 方法, 发现是 xxl-job 的线程，在 artahs 中执行 stack 命令：

[arthas@1]$ stack java.lang.Thread "<init>"

输出结果如下：

怀疑 xxl-job 的线程泄露

想着如果是这个原因应该线程增长到一定数量之后就会挂掉，等了等，发现线程增长一定数量（接近 400）后就不在增长了，尴尬…，又看了下线上之前跑的比较正常的服务，发现线上的线程数也是在接近 400 的数量级上一直很平稳，服务也很健康，应该也不会是这样原因，没有思路，暂时先将 TCP 的健康检查换成 HTTP 的保证服务挂掉的时候能够第一时间重启（后边分析了下，xxl-job 的线程增长会这么快，是因为，xxl-job 内置的 jetty 服务器的默认线程池为 256 个线程）。

第二次冲锋：再次排查

某热心同事大东子发现测试环境定时任务也挂了，查看了下测试环境的内存和线程池，发现基本和线上环境的是一样的，没有什么太大的异常，不过好在测试环境的是挂掉的现场，应该线索更多一点。

既然内存和线程没有发现什么太大的问题，那就从挂的服务的 CPU 看下能不能找到线索。进入终端，top 命令查看 CPU，果然有问题，CPU 已经跑满了，如下所示。

接下来进入 arthas 终端，使用 thread -n 3 查看 CPU 占用率最高的 3 个线程一直处于下面的两个堆栈：

这两个堆栈第一个是业务代码，其他两个都是 log4j2 打日志相关的。

接下来我们查看了一下业务代码，发现了下面这些细节：

线程卡住的地方是等待 Callable 任务结果，如果没有结果返回就会一直空转。
既然有任务没有结果，那么肯定 executorService 线程池有线程被一直 hold 住。
查看 executorService 线程池的定义, 线程池的线程名都是 school-thread 开头
如下图所示。

接下来使用 arthas 查看线程池中的线程堆栈：

[arthas@1]$ thread 525

发现是卡在 logger.error，而且最后的堆栈和占用 CPU 最高的 3 个堆栈中的两个完全一样

接下来查看 com.lmax.disruptor.MultiProducerSequencer.next 的源码，看起来应该 do while 循环是在 136 行LockSupport.parkNanos(1);一直在空转。

如果要确定确实是死循环的话。那么我们尝试通过 arthas watch 命令找出下面几个变量的值就知道是不是这样的

[arthas@1]$ watch com.lmax.disruptor.Sequence get "{returnObj}"

[arthas@24631]$ watch com.lmax.disruptor.util.Util getMinimumSequence "{returnObj}"
)

通过这几个值我们很容易就判断出来程序确实一直在空转。后面我们发现，其实就是当 log4j2 异步打日志时需要往 disruptor 的 ringbuffer 存储事件时，ringbuffer 满了，但是消费者处理不过来，导致获取下一个存储事件的位置一直拿不到而空转，这部分源码注释如下。

/**
    * @see Sequencer#next()
    */
   @Override
   public long next()
   {
       return next(1);
   }

   /**
    * @see Sequencer#next(int)
    */
   @Override
   public long next(int n)
   {
       if (n < 1)
       {
           thrownew IllegalArgumentException("n must be > 0");
       }

       long current;
       long next;

       do
       {
         	//获取事件发布者需要发布的序列值
           current = cursor.get();
           next = current + n;

					//wrapPoint 代表申请的序列绕RingBuffer一圈以后的位置
           long wrapPoint = next - bufferSize;

         	//获取事件处理者处理到的序列值
           long cachedGatingSequence = gatingSequenceCache.get();

           /**
           	* 1.事件发布者要申请的序列值大于事件处理者当前的序列值且事件发布者要申请的序列值减去环的长度要小于事件处理
             *   者的序列值。
             * 2.满足(1)，可以申请给定的序列。
             * 3.不满足(1)，就需要查看一下当前事件处理者的最小的序列值(可能有多个事件处理者)。如果最小序列值大于等于
             * 当前事件处理者的最小序列值大了一圈，那就不能申请了序列(申请了就会被覆盖)，
             * 针对以上值举例：400米跑道(bufferSize)，小明跑了599米(nextSequence)，小红(最慢消费者)跑了200米
             * (cachedGatingSequence)。小红不动，小明再跑一米就撞翻小红的那个点，叫做绕环点wrapPoint。
             * */
           if (wrapPoint > cachedGatingSequence || cachedGatingSequence > current)
           {
               long gatingSequence = Util.getMinimumSequence(gatingSequences, current);

               if (wrapPoint > gatingSequence)
               {
                   LockSupport.parkNanos(1); // TODO, should we spin based on the wait strategy?
                   continue;
               }

               gatingSequenceCache.set(gatingSequence);
           }
           elseif (cursor.compareAndSet(current, next))
           {
               break;
           }
       }
       while (true);

       return next;
   }

看堆栈和我们确认源码之后，发现应该是 log4j2 通过 disruptor 异步打日志时产生了 CPU 频繁空转导致服务 CPU 被打爆，进而导致服务异常。

接下来我们来本地复现问题：

1.验证思路，我们也用一个线程池然后疯狂打印日志，为了尽可能快的产生死循环的结果，我们尽可能的将 disruptor 的 RingbufferSize 设置的尽可能小，线上的是通过环境变量设置的， -DAsyncLogger.RingBufferSize=32768，本机同样，不过设置为 RingBufferSize 的最小值 1282.验证代码：

fun testLog(){
        var i = 0
        while(i < 250000){
            executorService.submit {
                LOGGER.debug("test $i")
            }
            i++
        }
        LOGGER.debug("commit finish")
}

3.多触发调用几次这个函数（不是必现的，可能需要多次才会出现），果然出现了和线上相同堆栈和结果。

那为什么会产生死循环呢，既然确认不是业务代码问题，感觉应该是 log4j2 和 disruptor 的 bug，找 github 的 issue，确实发现了有一些类似的情况，但又不完全一样，大半天的时间都在找 issue（结果其实是个误区）… 对这个方向太执着了,在这个误区瞎找了好久好久，最后搞到头大。

就去找热心同时小斌斌讨论了下，然后尝试重新 arthas 进入已挂掉的服务，发现了下面这些端倪：

查看所有的线程状态, 发现了一个 blocked 状态的 id 为 36 的线程
查看 36 的线程堆栈, 是被 35 的线程 blocked 住了
查看 35 线程的堆栈，看起来和前面的堆栈是一样的都是卡在了 com.lmax.disruptor.MultiProducerSequencer.next
再仔细看下，其实卡住的应该是kafka.clients.Metadata.update 270 行和 kafka.clients.Metadata.add 117 行
如下图所示。

其中 add 和 update 都是加 synchronized 方法锁的, 其实就是 MetaData 自己的 update 把自己 add 锁住。

那么为什么 MetaData 自己的 update 会把自己的 add 锁住呢？

还要看下我们的 log4j2 的日志配置

<CCloudKafka name="KafkaLogger" syncsend="false" >
     <Property name="bootstrap.servers">127.0.0.1:9092</Property>
     <PatternLayout pattern="[%d{yyyy-MM-dd HH:mm:ss.SSS}][%t][%level] %m%n"/>
</CCloudKafka>

 <Async name="async" includeLocation = "true">
<appender-ref ref="Console"/>
    <appender-ref ref="RollingFileInfo"/>
	  <appender-ref ref="RollingFileError"/>
    <appender-ref ref="AsyncMailer"/>
    <appender-ref ref="KafkaLogger"/>
</Async>

我们 log4j2 中配置了 Async 打印 log，同时引用了 4 个 appender，其中有一个是发送到 kafka 的，整个的日志打印和发送简单的流程如下如所示：

当 Ringbuffer 刚好被打满的时候
kafka 的定时更新元数据 update 同步方法会 log.debug 打印一条日志
当 log4j2 尝试把这个日志写入到 disruptor 的时候，会 MultiProducerSequencer.next 获取下一个可以插入存储的位置时，发现没有位置可以存入，就会进行 LockSupport.parkNanos 暂时阻塞 1ns，等待 disruptor 的消费者消费掉日志事件之后，删除掉事件空出一个位置
问题就发生在这个了，当 kafka 的 KafkaProducer 的 waitOnMetadata 方法尝试消费这个这个消息时，会先进行 MetaData 的元数据 add 这个 topic，但是 add 的时候发现没有办法拿到锁，因为已经被第 2 步的 update 获取到了，这个时候就发生了死锁，然后 disruptor 的 MultiProducerSequencer.next 一直在空转。然后空转的线程一直持续耗住 CPU，进而导致服务挂掉。
waitOnMetadata 方法源码如下所示：

问题到这里有些熟悉 log4j2 的同学可能会想到 Log4j2 中的异步日志实现方式有 AsyncAppender 和 AsyncLogger 两种，其中：

AsyncAppender 采用了 ArrayBlockingQueue 来保存需要异步输出的日志事件；
AsyncLogger 则使用了 Disruptor 框架来实现高吞吐。
我们下面的配置是异步 AsyncAppender 的方式，但是为什么会用到 Disruptor，其实是因为我们全局配置了 -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLogge

<Async name="async" includeLocation = "true">
    <appender-ref ref="Console"/>
      <appender-ref ref="RollingFileInfo"/>
      <appender-ref ref="RollingFileError"/>
    <appender-ref ref="AsyncMailer"/>
    <appender-ref ref="KafkaLogger"/>
</Async>

更多 AsyncAppender 和 AsyncLogger 的区别可参考这两个博客：

其实还有一个问题，没太想明白，为什么 xxl-job 的线程数会一直增长，然后处于 wait 状态，其实这个和 xxl-job 内置的 jetty 服务有关, 我们本地启动 xxl-job 执行器，随便执行一个定时任务，然后 debug 断点到 Thread.init()方法，就可以看到是 jetty 服务器启动的线程，而这个线程池 corePoolSize 和 corePoolSize 是 256 个，这个也就印证了为什么我们的定时任务服务启动之后会线程会一直增加然后到一定数量之后就不太变了，其实就是因为这个线程池的原因，这一部分的源码如下所示。

总结

总结问题: log4j2 异步打日志时，队列满，而且我们有使用 kafka 进行打印日志，kafka 刚好在队列满时出发了死锁导致 distuptor 死循环了

那么这个问题如何解决呢？其实就是设置队列满的时候的处理策略，如果不设置队列满了时的处理策略为丢弃，那么默认的 blocking，在队列满时异步就与同步无异了：

在 AsyncLogger 设置 -Dlog4j2.AsyncQueueFullPolicy=Discard
在 AsyncAppender 设置 <Async name="async" blocking="false" includeLocation = "true">
在设置丢弃策略时，默认只会丢弃 INFO 级别以下的，为了保险起见还应该设置丢弃日志的等级，如 -Dlog4j2.DiscardThreshold=ERROR。

这个问题的解决确实花了比较多的时间，从一开始的各种怀疑点到最后的一步步接近真像，其实还是比较艰难的，可谓一波三折，在很多误区搞了很久，花了很多的时间，但是最后到解决的那个时刻还是很开心的，开心到连车都刮了得换车门，不过这都不重要了。

中间自己对 log4j2 的不了解的以及容易忽略细节的问题还是暴露了出来，其实慢慢的一条线下来也有了一套解决方法的流程和思路，这个是感觉最欣慰的，最后还是要感谢张师傅和小斌斌的帮助，和他们讨论其实很多时候会把自己从误区拉回来，也会学到很多的解决问题的思路和方法。

一次线上 xxl-job 服务异常排查分析原创

问题描述

第一次冲锋：初步排查

查看线上的 APM，发现两个异常，

进入终端，用 arthas 查看服务器线程状态

arthas 查看 WATING 状态的线程堆栈

这些线程到底是谁创建的

怀疑 xxl-job 的线程泄露

第二次冲锋：再次排查

总结

为你推荐

浅析AbstractQueuedSynchronizer

推荐阅读

专题推荐

本月精选性能专题

本月精选线上案例

本月精选原创好文

联系我们

网媒渠道

友情链接