Java-анализ проблемы, связанной с нерегулярным зависанием запланированных онлайн-задач.

Java

фон проблемы

Я получил частые электронные письма с сигналами тревоги, и планирование запланированных задач не удалось. Проверка списка исполнителей xxl-job пуста, но служба снова исправна. Проверка исторических записей выполнения задач обнаружила, что исполнители уменьшаются в порядке. это онлайн-сервис, только сначала перезапустите, а затем нет журнала потоков. В то же время я пытаюсь получить доступ к интерфейсу проверки работоспособности службы. Обнаружено, что интерфейс проверки работоспособности недоступен. Он должен быть что служба зависла.Однако из-за проверки работоспособности TCP, настроенной службой, Whale Cloud не обнаружил аномалии службы (кровавый урок).

image-20200608145717678

image-20200608145736031

Подводя итог проблемному явлению: список исполнителей xxl-job пуст, обнаружение TCP нормальное, отображение службы нормальное, но доступ к интерфейсу проверки работоспособности http недоступен, и служба фактически находится в зависшем состоянии.

Предварительный процесс расследования:

  1. Проверьте онлайн APM и найдите две аномалии,

    1. Память кучи будет регулярно заполняться (заполненные - это Eden Space ---- задача расчета задачи по времени для принципала очень велика, это нормально, что она заполнена, и после просмотра количества GC, молодой GC и старый GC не слишком большая аномалия)-----Время зависания почти такое же, как и у обычной кучи памяти.После дампа памяти на линии проверить ее не проблема.Это временно исключено, что это вызвано проблемой с памятью.
    2. Обнаружено, что перезапущенный служебный пул потоков растет медленно, я не очень хорошо это понимаю, нормальный пул потоков не будет находиться в состоянии роста все время, и число роста также очень велико.
    image-20200607182405014 image-20200607182432676

  2. Войдите в терминал и используйте arthas для просмотра состояния потока сервера.

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

    image-20200607174740224

    image-20200607174849879

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

    image-20200607175302666

  4. Мастер Чжан внедрил метод инициализации потока и обнаружил, что это поток xxl-job.

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

    image-20200608175127546

  5. На тот момент было подозрение что нить xxl-job слилась.Я думал, что если нить увеличится до определенного числа, то он зависнет.Подождав, я обнаружил, что нить не увеличивается после определенной суммы( близко к 400), что смущает.. .., я также посмотрел на относительно нормальные сервисы, которые работали до оффлайна, и обнаружил, что количество онлайн-потоков стабильно на порядок приближается к 400, а служба также очень здорова.Это не должно быть причиной.Временно замените проверку работоспособности TCP на HTTP, чтобы гарантировать, что служба может быть перезапущена в первый раз, когда она зависает (после анализа рост потока xxl-job будет расти так быстро, потому что по умолчанию сервер причала, встроенный в xxl-job, имеет пул потоков 256 потоков).

Повторный процесс устранения неполадок:

  1. Dongjie обнаружил, что задача Test Encreme Exection также повесила, проверяя пул памяти и резьбы тестовой среды, обнаружил, что базовая и онлайн-среда одинаковы, не слишком много ненормального, но хорошо в тестовой среде висит. На сцене должно быть больше подсказков.

  2. Поскольку серьезных проблем с памятью и потоками нет, посмотрите, сможете ли вы найти подсказки от ЦП зависшего сервиса.

    1. Войдите в терминал и используйте команду top, чтобы проверить процессор.Конечно, есть проблема.ЦП заполнен.

      image-20200607185834358

    2. Войдите в терминал Артаса

      thread -n 3 查看CPU占用率最高的3个线程一直处于下面的两个堆栈，
	1. 第一个是业务代码
	2. 其他两个都是log4j2 打日志相关的

      image-20200607190042958

  3. Посмотреть бизнес-код:

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

    image-20200607191156065

  4. arthas просматривает стек потоков в пуле потоков

    [arthas@1]$ thread 525
发现是卡在 logger.error，而且最后的堆栈和占用CPU最高的3个堆栈中的两个完全一样

    image-20200607191530249

    image-20200607191625547

  5. 查看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;
    }

  6. Посмотрев на стек и подтвердив исходный код, мы обнаружили, что должно быть так, что log4j2 генерировал бесконечный цикл при асинхронной регистрации через дисраптор, что приводило к взрыву ЦП службы, что, в свою очередь, приводило к зависанию службы.

  7. Локальная проверка (восстановление проблемы):

    1. Чтобы проверить идею, мы также используем пул потоков, а затем безумно печатаем журнал.Чтобы сгенерировать результат бесконечного цикла как можно быстрее, мы стараемся установить RingbufferSize разрушителя как можно меньше. устанавливаются через переменные среды, - DAsyncLogger.RingBufferSize=32768, то же самое для этой машины, но установлено минимальное значение RingBufferSize 128

    2. Проверочный код:

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

    3. Триггер для вызова этой функции несколько раз (это не обязательно, для ее появления может потребоваться несколько раз), и появится тот же стек и результат, что и в строке.

  8. Тогда почему бесконечный цикл?Поскольку подтверждено, что это не проблема бизнес-кода, я чувствую, что это должна быть ошибка log4j2 и разрушителя.Я искал проблему github и обнаружил, что есть некоторые похожие ситуации, но они не совсем совпадают.Большую часть времени находится в поиске проблемы(результат на самом деле недоразумение).........я слишком настойчив в этом направлении.ищу давно в этом недоразумении, и, наконец, получил большую голову.

  9. Я пошел к Xing Bin, чтобы обсудить это, обсуждение было действительно полезным, я нашел другие проблемы с разных направлений (спасибо Xing Bin за идеи и сомнения), и re-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锁住

    image-20200607195353525

    image-20200607195525041

    image-20200607195804538

  10. Так почему же собственное обновление MetaData блокирует собственное добавление? Также посмотрите на нашу конфигурацию журнала 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>

    image-20200607202510876

    我们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，进而导致服务挂掉

    image-20200607203413471

  11. Проблемы, из-за которых некоторые знакомые студенты log4j2 могут спросить, есть ли два способа асинхронного log4j2.

    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/

  12. На самом деле есть еще одна проблема.. Я не очень понимаю, почему количество потоков xxl-job все увеличивается, а затем ждет. На самом деле это связано со встроенным сервисом jetty xxl-job. xxl-job executor локально и выполнить его случайным образом.Временная задача, а затем отладить точку останова в методе Thread.init(), вы можете видеть, что поток, запущенный сервером причала, и пул потоков corePoolSize и corePoolSize равны 256 , что также доказывает, почему запускается наш сервис задач с таймером После этого количество потоков будет продолжать увеличиваться, а затем не изменится после определенного числа.На самом деле, это из-за этого пула потоков.

    image-20200608142924653

    image-20200608142220513

Суммировать

  1. Решать проблему

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

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


1. AsyncLogger 设置
    -Dlog4j2.AsyncQueueFullPolicy=Discard
2. AsyncAppender 
    <Async name="async" blocking="false" includeLocation = "true">
    
如果设置丢弃策略时，还需要设置丢弃日志的等级：根据项目情况按需配置：-Dlog4j2.DiscardThreshold=INFO

  2. Суммировать

    这个问题的解决确实花了比较多的时间，从一开始的各种怀疑点到最后的一步步接近真像，其实还是比较艰难的，在
很多误区搞了很久，花了很多的时间，但是最后到解决的那个时刻还是很开心的，不过中间自己对log4j2的不了解
的以及容易忽略细节的问题还是暴露了出来，其实慢慢的一条线下来也有了一套解决方法的流程和思路，这个是感觉
最欣慰的，最后还是要感谢张师傅和幸斌的帮助，和他们讨论其实很多时候会把自己从误区拉回来，也会学到很多的
解决问题的思路和方法。
Категории