Java-線上定時任務不按期掛掉問題分析

時間 2020-06-09

標籤 java 線上定時任務按期掛掉問題分析欄目 Java 简体版

原文原文鏈接

問題背景

收到頻繁的告警郵件，定時任務調度失敗，查看xxl-job的執行器列表是空的，可是服務又顯示健康，查看歷史任務執行記錄發現執行器是依次遞減，因爲是線上服務，只能先重啓，而後線程日誌也沒有，同時嘗試訪問服務的健康檢查接口，發現健康檢查接口訪問不通，應該是服務已經掛了，可是由於服務配置的TCP健康檢查，沒鯨雲沒有檢測出來服務異常（血淋淋的教訓）。java

總結問題現象：xxl-job的執行器列表爲空，TCP檢測正常，服務顯示正常，可是http健康檢查接口訪問不了，服務其實處於掛掉狀態。git

初步排查過程:

查看線上的APM，發現兩個異常，github
1. 堆內存會按期處於打滿的狀態（被打滿的都是 Eden Space----校長的定時任務計算任務很大，打滿也是正常的，並且看了GC次數，young GC 和 old GC也沒有太大異常）-----掛掉的時刻和正常狀況的堆內存幾乎是相同的規律，dump出線上的內存後，查看也沒有什麼問題，暫時排除是內存問題致使
2. 發現重啓的服務線程池一直在緩慢的增加，不是很理解，正常的線程池不會一直處於增加的狀態，並且增加的數量也很大

進入終端，用arthas查看服務器線程狀態apache

arthas 進入終端，執行thread命令
確實發現不少的線程處於WATING狀態，dump出線程堆棧，發現有200多個線程處於WATING狀態。
複製代碼

arthas 查看WATING狀態的線程堆棧, 發現全部線程都處於下面的堆棧，看不出什麼太多的線索，代碼中查看是否是有什麼地方設置了無限線程的線程池，發現也沒有這麼挫的操做。
複製代碼

張師傅注入線程的init方法, 發現是xxl-job的線程bootstrap
```
[arthas@1]$ stack java.lang.Thread "<init>"
複製代碼
```
當時是懷疑xxl-job的線程泄露，想着若是是這個緣由應該線程增加到必定數量以後就會掛掉，等了等，發現線程增加必定數量（接近400）後就不在增加了，尷尬...., 又看了下線上以前跑的比較正常的服務，發現線上的線程數也是在接近400的數量級上一直很平穩，服務也很健康，應該也不會是這樣緣由，沒有思路，暫時先將TCP的健康檢查換成HTTP的保證服務掛掉的時候可以第一時間重啓（後邊分析了下，xxl-job的線程增加會這麼快，是由於，xxl-job內置的jetty服務器的默認線程池爲256個線程）。bash

再次排查過程：

東傑發現測試環境定時任務也掛了，查看了下測試環境的內存和線程池，發現基本和線上環境的是同樣的，沒有什麼太大的異常，不過好在測試環境的是掛掉的現場，應該線索更多一點。服務器
既然內存和線程沒有發現什麼太大的問題，那就從掛的服務的CPU看下能不能找到線索app
1. 進入終端，top命令查看CPU，果真有問題，CPU已經跑滿框架
2. 進入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被打爆，進而致使服務掛掉。
本地驗證( 復現問題 )：
1. 驗證思路，咱們也用一個線程池而後瘋狂打印日誌，爲了儘量快的產生死循環的結果，咱們儘量的將disruptor 的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. 多觸發調用幾回這個函數（不是必現的，可能須要屢次纔會出現），果真出現了和線上相同堆棧和結果
那爲何會產生死循環呢，既然確認不是業務代碼問題，感受應該是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的不瞭解
的以及容易忽略細節的問題仍是暴露了出來，其實慢慢的一條線下來也有了一套解決方法的流程和思路，這個是感受
最欣慰的，最後仍是要感謝張師傅和幸斌的幫助，和他們討論其實不少時候會把本身從誤區拉回來，也會學到不少的
解決問題的思路和方法。

複製代碼