Java線上定時(shí)任務(wù)不定期掛掉問題分析

問題背景

收到頻繁的告警郵件，定時(shí)任務(wù)調(diào)度失敗，查看xxl-job的執(zhí)行器列表是空的，但是服務(wù)又顯示健康。

查看歷史任務(wù)執(zhí)行記錄發(fā)現(xiàn)執(zhí)行器是依次遞減，由于是線上服務(wù)，只能先重啟，然后線程日志也沒有，同時(shí)嘗試訪問服務(wù)的健康檢查接口，發(fā)現(xiàn)健康檢查接口訪問不通，應(yīng)該是服務(wù)已經(jīng)掛了，但是因?yàn)榉?wù)配置的TCP健康檢查，沒鯨云沒有檢測(cè)出來服務(wù)異常（血淋淋的教訓(xùn)）。

file
file

總結(jié)問題現(xiàn)象：xxl-job的執(zhí)行器列表為空，TCP檢測(cè)正常，服務(wù)顯示正常，但是http健康檢查接口訪問不了，服務(wù)其實(shí)處于掛掉狀態(tài)。

初步排查過程

1、查看線上的APM，發(fā)現(xiàn)兩個(gè)異常

堆內(nèi)存會(huì)定期處于打滿的狀態(tài) （被打滿的都是 Eden Space----校長(zhǎng)的定時(shí)任務(wù)計(jì)算任務(wù)很大，打滿也是正常的，而且看了GC次數(shù)，young GC 和 old GC也沒有太大異常）-----掛掉的時(shí)刻和正常情況的堆內(nèi)存幾乎是相同的規(guī)律，dump出線上的內(nèi)存后，查看也沒有什么問題，暫時(shí)排除是內(nèi)存問題導(dǎo)致。

發(fā)現(xiàn)重啟的服務(wù)線程池一直在緩慢的增長(zhǎng)，不是很理解，正常的線程池不會(huì)一直處于增長(zhǎng)的狀態(tài)，而且增長(zhǎng)的數(shù)量也很大。

file
file

2、進(jìn)入終端，用arthas查看服務(wù)器線程狀態(tài)

arthas 進(jìn)入終端，執(zhí)行thread命令。

確實(shí)發(fā)現(xiàn)很多的線程處于WATING狀態(tài)，dump出線程堆棧，發(fā)現(xiàn)有200多個(gè)線程處于WATING狀態(tài)。

file
file

3、arthas 查看WATING狀態(tài)的線程堆棧

發(fā)現(xiàn)所有線程都處于下面的堆棧，看不出什么太多的線索，代碼中查看是不是有什么地方設(shè)置了無限線程的線程池，發(fā)現(xiàn)也沒有這么挫的操作。

Uploading file...

張師傅注入線程的init方法, 發(fā)現(xiàn)是xxl-job的線程

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

當(dāng)時(shí)是懷疑xxl-job的線程泄露，想著如果是這個(gè)原因應(yīng)該線程增長(zhǎng)到一定數(shù)量之后就會(huì)掛掉，等了等，發(fā)現(xiàn)線程增長(zhǎng)一定數(shù)量（接近400）后就不在增長(zhǎng)了……

又看了下線上之前跑的比較正常的服務(wù)，發(fā)現(xiàn)線上的線程數(shù)也是在接近400的數(shù)量級(jí)上一直很平穩(wěn)，服務(wù)也很健康，應(yīng)該也不會(huì)是這樣原因，沒有思路，暫時(shí)先將TCP的健康檢查換成HTTP的保證服務(wù)掛掉的時(shí)候能夠第一時(shí)間重啟（后邊分析了下，xxl-job的線程增長(zhǎng)會(huì)這么快，是因?yàn)?，xxl-job內(nèi)置的jetty服務(wù)器的默認(rèn)線程池為256個(gè)線程）。

再次排查過程

1、同事發(fā)現(xiàn)測(cè)試環(huán)境定時(shí)任務(wù)也掛了，查看了下測(cè)試環(huán)境的內(nèi)存和線程池，發(fā)現(xiàn)基本和線上環(huán)境的是一樣的，沒有什么太大的異常，不過好在測(cè)試環(huán)境的是掛掉的現(xiàn)場(chǎng)，應(yīng)該線索更多一點(diǎn)。

2、既然內(nèi)存和線程沒有發(fā)現(xiàn)什么太大的問題，那就從掛的服務(wù)的CPU看下能不能找到線索。

進(jìn)入終端，top命令查看CPU，果然有問題，CPU已經(jīng)跑滿

Uploading file...

進(jìn)入arthas終端

thread -n 3 查看CPU占用率最高的3個(gè)線程一直處于下面的兩個(gè)堆棧

第一個(gè)是業(yè)務(wù)代碼，其他兩個(gè)都是log4j2 打日志相關(guān)的。

file

3、查看業(yè)務(wù)代碼：

  • 線程卡住的地方是等待Callable任務(wù)結(jié)果，如果沒有結(jié)果返回就會(huì)一直空轉(zhuǎn)。
  • 既然有任務(wù)沒有結(jié)果，那么肯定 executorService 線程池有線程被一直hold住。
  • 查看executorService 線程池的定義, 線程池的線程名都是 school-thread開頭

4、arthas查看線程池中的線程堆棧

[arthas@1]$ thread 525

發(fā)現(xiàn)是卡在 logger.error，而且最后的堆棧和占用CPU最高的3個(gè)堆棧中的兩個(gè)完全一樣。

Uploading file...
file

5、查看com.lmax.disruptor.MultiProducerSequencer.next的源碼，看起來應(yīng)該do while循環(huán)是在136行（LockSupport.parkNanos(1);）一直在空轉(zhuǎn)。

如果要確定確實(shí)是死循環(huán)的話。那么我們嘗試通過arthas watch命令找出下面幾個(gè)變量的值就知道是不是這樣的

ex.
[arthas@1]$ watch com.lmax.disruptor.Sequence get "{returnObj}" 
    current：獲取事件發(fā)布者需要發(fā)布的序列值
    cachedGatingSequence：獲取事件處理者處理到的序列值
[arthas@24631]$ watch com.lmax.disruptor.util.Util getMinimumSequence "{returnObj}"
    gatingSequence：當(dāng)前事件處理者的最小的序列值(可能有多個(gè)事件處理者)
    bufferSize： 128
    n: 1

通過這幾個(gè)值我們很容易就判斷出來程序確實(shí)一直在空轉(zhuǎn)。

其實(shí)就是當(dāng)log4j2 異步打日志時(shí)需要往disruptor 的ringbuffer存儲(chǔ)事件時(shí)，ringbuffer滿了，但是消費(fèi)者處理不過來，導(dǎo)致獲取下一個(gè)存儲(chǔ)事件的位置一直拿不到而空轉(zhuǎn)。

  /**
     * @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
        {
            //獲取事件發(fā)布者需要發(fā)布的序列值
            current = cursor.get();
            next = current + n;
          
                        //wrapPoint 代表申請(qǐng)的序列繞RingBuffer一圈以后的位置
            long wrapPoint = next - bufferSize;
          
            //獲取事件處理者處理到的序列值
            long cachedGatingSequence = gatingSequenceCache.get();
                        
            /** 
                * 1.事件發(fā)布者要申請(qǐng)的序列值大于事件處理者當(dāng)前的序列值且事件發(fā)布者要申請(qǐng)的序列值減去環(huán)的長(zhǎng)度要小于事件處理
              *   者的序列值。
              * 2.滿足(1)，可以申請(qǐng)給定的序列。
              * 3.不滿足(1)，就需要查看一下當(dāng)前事件處理者的最小的序列值(可能有多個(gè)事件處理者)。如果最小序列值大于等于
              * 當(dāng)前事件處理者的最小序列值大了一圈，那就不能申請(qǐng)了序列(申請(qǐng)了就會(huì)被覆蓋)，
              * 針對(duì)以上值舉例：400米跑道(bufferSize)，小明跑了599米(nextSequence)，小紅(最慢消費(fèi)者)跑了200米   
              * (cachedGatingSequence)。小紅不動(dòng)，小明再跑一米就撞翻小紅的那個(gè)點(diǎn)，叫做繞環(huán)點(diǎn)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、看堆棧和我們確認(rèn)源碼之后，發(fā)現(xiàn)應(yīng)該是log4j2 通過disruptor異步打日志時(shí)產(chǎn)生了死循環(huán)導(dǎo)致服務(wù)CPU被打爆，進(jìn)而導(dǎo)致服務(wù)掛掉。

7、本地驗(yàn)證( 復(fù)現(xiàn)問題 )：

1）驗(yàn)證思路，我們也用一個(gè)線程池然后瘋狂打印日志，為了盡可能快的產(chǎn)生死循環(huán)的結(jié)果，我們盡可能的將disruptor 的RingbufferSize設(shè)置的盡可能小，線上的是通過環(huán)境變量設(shè)置的，-DAsyncLogger.RingBufferSize=32768，本機(jī)同樣，不過設(shè)置為RingBufferSize的最小值 128

2）驗(yàn)證代碼：

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

3）多觸發(fā)調(diào)用幾次這個(gè)函數(shù)（不是必現(xiàn)的，可能需要多次才會(huì)出現(xiàn)），果然出現(xiàn)了和線上相同堆棧和結(jié)果。

8、那為什么會(huì)產(chǎn)生死循環(huán)呢，既然確認(rèn)不是業(yè)務(wù)代碼問題，感覺應(yīng)該是log4j2和disruptor的bug，找github的issue，確實(shí)發(fā)現(xiàn)了有一些類似的情況，但又不完全一樣，大半天的時(shí)間都在找issue（結(jié)果其實(shí)是個(gè)誤區(qū)）........

對(duì)這個(gè)方向太執(zhí)著了，在這個(gè)誤區(qū)瞎找了好久好久，最后搞到頭大。

9、去找同事討論了下，討論真的有用，從不同的思路方向發(fā)現(xiàn)了其他的問題，重新arthas進(jìn)入已掛掉的服務(wù)。

  • 查看所有的線程狀態(tài), 發(fā)現(xiàn)了一個(gè)blocked狀態(tài)的id為36 的線程
  • 查看36的線程堆棧, 是被35的線程blocked住了
  • 查看35線程的堆棧，看起來和前面的堆棧是一樣的都是卡在了 com.lmax.disruptor.MultiProducerSequencer.next
  • 再仔細(xì)看下，其實(shí)卡住的應(yīng)該是
    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鎖的， 其實(shí)就是MetaData自己的update把自己add鎖住

file
file
file

10、那么為什么MetaData自己的update會(huì)把自己的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，同時(shí)引用了4個(gè)appender，其中有一個(gè)是發(fā)送到kafka的，整個(gè)的日志打印和發(fā)送簡(jiǎn)單的流程如下所示

為什么會(huì)鎖住呢？

  • 當(dāng)Ringbuffer剛好被打滿的時(shí)候
  • kafka的定時(shí)更新元數(shù)據(jù)update同步方法會(huì)log.debug 打印一條日志
  • 當(dāng)log4j2 嘗試把這個(gè)日志寫入到disruptor的時(shí)候，會(huì)MultiProducerSequencer.next獲取下一個(gè)可以插入存儲(chǔ)的位置時(shí)，發(fā)現(xiàn)沒有位置可以存入，就會(huì)進(jìn)行LockSupport.parkNanos暫時(shí)阻塞1ns，等待disruptor的消費(fèi)者消費(fèi)掉日志事件之后，刪除掉事件空出一個(gè)位置
  • 問題就發(fā)生在這個(gè)了，當(dāng)kafka的KafkaProducer的waitOnMetadata方法嘗試消費(fèi)這個(gè)這個(gè)消息時(shí)，會(huì)先進(jìn)行MetaData的元數(shù)據(jù)add這個(gè)topic，但是add的時(shí)候發(fā)現(xiàn)沒有辦法拿到鎖，因?yàn)橐呀?jīng)被第2步的update 獲取到了，這個(gè)時(shí)候就發(fā)生了死鎖，然后disruptor的MultiProducerSequencer.next一直在空轉(zhuǎn)。

然后空轉(zhuǎn)的線程一直持續(xù)耗住CPU，進(jìn)而導(dǎo)致服務(wù)掛掉。

file

11、問題到這里有些熟悉log4j2的同學(xué)可能會(huì)問到log4j2 的異步有2種方式。

Log4j2中的異步日志實(shí)現(xiàn)方式有AsyncAppender和AsyncLogger兩種。

其中：

  • AsyncAppender采用了ArrayBlockingQueue來保存需要異步輸出的日志事件；
  • AsyncLogger則使用了Disruptor框架來實(shí)現(xiàn)高吞吐。

我們下面的配置是異步AsyncAppender的方式，但是為什么會(huì)用到Disruptor，其實(shí)是因?yàn)槲覀內(nèi)峙渲昧恕?/p>

-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector ，這個(gè)會(huì)讓應(yīng)用使用Disruptor來實(shí)現(xiàn)異步。

<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>

其實(shí)還有一個(gè)問題，沒太想明白，為什么xxl-job的線程數(shù)會(huì)一直增長(zhǎng)，然后處于wait狀態(tài)？

其實(shí)這個(gè)和xxl-job內(nèi)置的jetty服務(wù)有關(guān)，我們本地啟動(dòng)xxl-job執(zhí)行器，隨便執(zhí)行一個(gè)定時(shí)任務(wù)，然后debug斷點(diǎn)到Thread.init()方法，就可以看到是jetty服務(wù)器啟動(dòng)的線程。

而這個(gè)線程池corePoolSize 和corePoolSize是256個(gè)，這個(gè)也就印證了為什么我們的定時(shí)任務(wù)服務(wù)啟動(dòng)之后會(huì)線程會(huì)一直增加然后到一定數(shù)量之后就不太變了，其實(shí)就是因?yàn)檫@個(gè)線程池的原因。

file
file

總結(jié)

log4j2 異步打日志時(shí)，隊(duì)列滿，而且我們有使用kafka進(jìn)行打印日志，kafka剛好在隊(duì)列滿時(shí)出發(fā)了死鎖導(dǎo)致distuptor死循環(huán)了。

那么這個(gè)問題如何解決呢？其實(shí)就是設(shè)置隊(duì)列滿的時(shí)候的處理策略
設(shè)置隊(duì)列滿了時(shí)的處理策略：丟棄，否則默認(rèn)blocking，異步就與同步無異了。

1、AsyncLogger 設(shè)置

    -Dlog4j2.AsyncQueueFullPolicy=Discard

2、AsyncAppender

    <Async name="async" blocking="false" includeLocation = "true">

如果設(shè)置丟棄策略時(shí)，還需要設(shè)置丟棄日志的等級(jí)。根據(jù)項(xiàng)目情況按需配置：-Dlog4j2.DiscardThreshold=INFO

作者：IKNOW本尊

鏈接：https://juejin.im/post/5edcf10451882543345e9899

文源網(wǎng)絡(luò)，僅供學(xué)習(xí)之用，如有侵權(quán)請(qǐng)聯(lián)系刪除。

我將面試題和答案都整理成了PDF文檔，還有一套學(xué)習(xí)資料，涵蓋Java虛擬機(jī)、spring框架、Java線程、數(shù)據(jù)結(jié)構(gòu)、設(shè)計(jì)模式等等，但不僅限于此。

關(guān)注公眾號(hào)【java圈子】獲取資料，還有優(yōu)質(zhì)文章每日送達(dá)。

file
?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請(qǐng)聯(lián)系作者
【社區(qū)內(nèi)容提示】社區(qū)部分內(nèi)容疑似由AI輔助生成，瀏覽時(shí)請(qǐng)結(jié)合常識(shí)與多方信息審慎甄別。
平臺(tái)聲明：文章內(nèi)容（如有圖片或視頻亦包括在內(nèi)）由作者上傳并發(fā)布，文章內(nèi)容僅代表作者本人觀點(diǎn)，簡(jiǎn)書系信息發(fā)布平臺(tái)，僅提供信息存儲(chǔ)服務(wù)。

友情鏈接更多精彩內(nèi)容