问题背景
收到频繁的告警邮件，定时任务调度失败，查看xxl-job的执行器列表是空的，但是服务又显示健康，查看历史任务执行记录发现执行器是依次递减，由于是线上服务，只能先重启，然后线程日志也没有，同时尝试访问服务的健康检查接口，发现健康检查接口访问不通，应该是服务已经挂了，但是因为服务配置的TCP健康检查，没鲸云没有检测出来服务异常（血淋淋的教训）。
总结问题现象：xxl-job的执行器列表为空，TCP检测正常，服务显示正常，但是http健康检查接口访问不了，服务其实处于挂掉状态。
初步排查过程:
-
查看线上的APM，发现两个异常，
- 堆内存会定期处于打满的状态 （被打满的都是 Eden Space----校长的定时任务计算任务很大，打满也是正常的，而且看了GC次数，young GC 和 old GC也没有太大异常）-----挂掉的时刻和正常情况的堆内存几乎是相同的规律，dump出线上的内存后，查看也没有什么问题，暂时排除是内存问题导致
- 发现重启的服务线程池一直在缓慢的增长，不是很理解，正常的线程池不会一直处于增长的状态，而且增长的数量也很大
-
进入终端，用arthas查看服务器线程状态
arthas 进入终端，执行thread命令 确实发现很多的线程处于WATING状态，dump出线程堆栈，发现有200多个线程处于WATING状态。 复制代码 -
arthas 查看WATING状态的线程堆栈, 发现所有线程都处于下面的堆栈，看不出什么太多的线索，代码中查看是不是有什么地方设置了无限线程的线程池，发现也没有这么挫的操作。 复制代码 -
张师傅注入线程的init方法, 发现是xxl-job的线程
[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个线程一直处于下面的两个堆栈， 1. 第一个是业务代码 2. 其他两个都是log4j2 打日志相关的 复制代码
-
-
查看业务代码：
1. 线程卡住的地方是等待Callable任务结果，如果没有结果返回就会一直空转。 2. 既然有任务没有结果，那么肯定 executorService 线程池有线程被一直hold住。 3. 查看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命令找出下面几个变量的值就知道是不是这样的 ex. [arthas@1]$ watch com.lmax.disruptor.Sequence get "{returnObj}" current：获取事件发布者需要发布的序列值 cachedGatingSequence：获取事件处理者处理到的序列值 [arthas@24631]$ watch com.lmax.disruptor.util.Util getMinimumSequence "{returnObj}" gatingSequence：当前事件处理者的最小的序列值(可能有多个事件处理者) bufferSize： 128 n: 1 通过这几个值我们很容易就判断出来程序确实一直在空转 其实就是当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) { throw new 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); } else if (cursor.compareAndSet(current, next)) { break; } } while (true); return next; } 复制代码 -
看堆栈和我们确认源码之后，发现应该是log4j2 通过disruptor异步打日志时产生了死循环导致服务CPU被打爆，进而导致服务挂掉。
-
本地验证( 复现问题 )：
-
验证思路，我们也用一个线程池然后疯狂打印日志，为了尽可能快的产生死循环的结果，我们尽可能的将disruptor 的RingbufferSize设置的尽可能小，线上的是通过环境变量设置的， -DAsyncLogger.RingBufferSize=32768，本机同样，不过设置为RingBufferSize的最小值 128
-
验证代码：
fun testLog(){ var i = 0 while(i < 250000){ executorService.submit { LOGGER.debug("test $i") } i++ } LOGGER.debug("commit finish") } 复制代码 -
多触发调用几次这个函数（不是必现的，可能需要多次才会出现），果然出现了和线上相同堆栈和结果
-
-
那为什么会产生死循环呢，既然确认不是业务代码问题，感觉应该是log4j2和disruptor的bug，找github的issue，确实发现了有一些类似的情况，但又不完全一样，大半天的时间都在找issue（结果其实是个误区）........ 对这个方向太执着了,在这个误区瞎找了好久好久，最后搞到头大。
-
就去找幸斌讨论了下，讨论真的有用，从不同的思路方向发现了其他的问题（感谢幸斌提供的思路和疑点），重新arthas进入已挂掉的服务
1. 查看所有的线程状态, 发现了一个blocked状态的id为36 的线程 2. 查看36的线程堆栈, 是被35的线程blocked住了 3. 查看35线程的堆栈，看起来和前面的堆栈是一样的都是卡在了 com.lmax.disruptor.MultiProducerSequencer.next 4. 再仔细看下，其实卡住的应该是 kafka.clients.Metadata.update 270行 和 Objects.requireNonNull(topic, "topic cannot be null"); kafka.clients.Metadata.add 117 行 log.debug("Updated cluster metadata version {} to {}", this.version, this.cluster); 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的，整个的日志打印和发送简单的流程如下如所示 为什么会锁住呢？ 1. 当Ringbuffer刚好被打满的时候 2. kafka的定时更新元数据update同步方法会log.debug 打印一条日志 3. 当log4j2 尝试把这个日志写入到disruptor的时候，会MultiProducerSequencer.next获取下一个可以插入存储的位置时，发现没有位置可以存入，就会进行LockSupport.parkNanos暂时阻塞1ns，等待disruptor的消费者消费掉日志事件之后，删除掉事件空出一个位置 4. 问题就发生在这个了，当kafka的KafkaProducer的waitOnMetadata方法尝试消费这个这个消息时，会先进行MetaData的元数据add这个topic，但是add的时候发现没有办法拿到锁，因为已经被第2步的update 获取到了，这个时候就发生了死锁，然后disruptor的MultiProducerSequencer.next一直在空转。 然后空转的线程一直持续耗住CPU，进而导致服务挂掉 复制代码 -
问题到这里有些熟悉log4j2的同学可能会问到log4j2 的异步有2种方式
Log4j2中的异步日志实现方式有AsyncAppender和AsyncLogger两种。 其中： AsyncAppender采用了ArrayBlockingQueue来保存需要异步输出的日志事件； AsyncLogger则使用了Disruptor框架来实现高吞吐。 我们下面的配置是异步AsyncAppender的方式，但是为什么会用到Disruptor，其实是因为我们全局配置了 -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector，这个会让应用使用Disruptor来实现异步。 复制代码<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的区别可参考这两个博客 https://bryantchang.github.io/2019/01/15/log4j2-asyncLogger/ https://bryantchang.github.io/2018/11/18/log4j-async/ 复制代码 -
其实还有一个问题，没太想明白，为什么xxl-job的线程数会一直增长，然后处于wait状态，其实这个和xxl-job内置的jetty服务有关, 我们本地启动xxl-job执行器，随便执行一个定时任务，然后debug断点到Thread.init()方法，就可以看到是jetty服务器启动的线程，而这个线程池corePoolSize 和corePoolSize是256个，这个也就印证了为什么我们的定时任务服务启动之后会线程会一直增加然后到一定数量之后就不太变了，其实就是因为这个线程池的原因。
总结
-
解决问题
总结问题: log4j2 异步打日志时，队列满，而且我们有使用kafka进行打印日志，kafka刚好在队列满时出发了死锁导致distuptor死循环了 那么这个问题如何解决呢？其实就是设置队列满的时候的处理策略 设置队列满了时的处理策略：丢弃，否则默认blocking，异步就与同步无异了 1. AsyncLogger 设置 -Dlog4j2.AsyncQueueFullPolicy=Discard 2. AsyncAppender <Async name="async" blocking="false" includeLocation = "true"> 如果设置丢弃策略时，还需要设置丢弃日志的等级：根据项目情况按需配置：-Dlog4j2.DiscardThreshold=INFO 复制代码 -
总结
这个问题的解决确实花了比较多的时间，从一开始的各种怀疑点到最后的一步步接近真像，其实还是比较艰难的，在 很多误区搞了很久，花了很多的时间，但是最后到解决的那个时刻还是很开心的，不过中间自己对log4j2的不了解 的以及容易忽略细节的问题还是暴露了出来，其实慢慢的一条线下来也有了一套解决方法的流程和思路，这个是感觉 最欣慰的，最后还是要感谢张师傅和幸斌的帮助，和他们讨论其实很多时候会把自己从误区拉回来，也会学到很多的 解决问题的思路和方法。 复制代码
近期评论