国产福利91精品一区,四虎在线高清视频,国产白丝在线观看

作者：IKNOW本尊

問題背景

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

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

初步排查過程:

1.查看線上的APM，發現兩個異常:

堆內存會定期處于打滿的狀態（被打滿的都是 Eden Space----校長的定時任務計算任務很大，打滿也是正常的，而且看了GC次數，young GC 和 old GC也沒有太大異常）-----掛掉的時刻和正常情況的堆內存幾乎是相同的規律，dump出現上的內存后，查看也沒有什么問題，暫時排除是內存問題導致
發現重啟的服務線程池一直在緩慢的增長，不是很理解，正常的線程池不會一直處于增長的狀態，而且增長的數量也很大

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

 arthas 進入終端，執行thread命令
 確實發現很多的線程處于WATING狀態，dump出線程堆棧，發現有200多個線程處于WATING狀態。

3.arthas 查看WATING狀態的線程堆棧, 發現所有線程都處于下面的堆棧，看不出什么太多的線索，代碼中查看是不是有什么地方設置了無限線程的線程池，發現也沒有這么挫的操作。

4.張師傅注入線程的init方法, 發現是xxl-job的線程

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

5.當時是懷疑xxl-job的線程泄露，想著如果是這個原因應該線程增長到一定數量之后就會掛掉，等了等，發現線程增長一定數量（接近400）后就不在增長了，尷尬...., 又看了下線上之前跑的比較正常的服務，發現線上的線程數也是在接近400的數量級上一直很平穩，服務也很健康，應該也不會是這樣原因，沒有思路，暫時先將TCP的健康檢查換成HTTP的保證服務掛掉的時候能夠第一時間重啟（后邊分析了下，xxl-job的線程增長會這么快，是因為，xxl-job內置的jetty服務器的默認線程池為256個線程）。

再次排查過程：

1.東杰發現測試環境定時任務也掛了，查看了下測試環境的內存和線程池，發現基本和線上環境的是一樣的，沒有什么太大的異常，不過好在測試環境的是掛掉的現場，應該線索更多一點。

2.既然內存和線程沒有發現什么太大的問題，那就從掛的服務的CPU看下能不能找到線索

進入終端，top命令查看CPU，果然有問題，CPU已經跑滿

進入arthas終端

thread -n 3 查看CPU占用率最高的3個線程一直處于下面的兩個堆棧，
1. 第一個是業務代碼
2. 其他兩個都是log4j2 打日志相關的

3.查看業務代碼：

 1. 線程卡住的地方是等待Callable任務結果，如果沒有結果返回就會一直空轉。
 2. 既然有任務沒有結果，那么肯定 executorService 線程池有線程被一直hold住。
 3. 查看executorService 線程池的定義, 線程池的線程名都是 school-thread開頭

4.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;
    }

6.看堆棧和我們確認源碼之后，發現應該是log4j2 通過disruptor異步打日志時產生了死循環導致服務CPU被打爆，進而導致服務掛掉。

7.本地驗證( 復現問題 )：

驗證思路，我們也用一個線程池然后瘋狂打印日志，為了盡可能快的產生死循環的結果，我們盡可能的將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")
}

多觸發調用幾次這個函數（不是必現的，可能需要多次才會出現），果然出現了和線上相同堆棧和結果

8.那為什么會產生死循環呢，既然確認不是業務代碼問題，感覺應該是log4j2和disruptor的bug，找github的issue，確實發現了有一些類似的情況，但又不完全一樣，大半天的時間都在找issue（結果其實是個誤區）........ 對這個方向太執著了,在這個誤區瞎找了好久好久，最后搞到頭大。

9.就去找幸斌討論了下，討論真的有用，從不同的思路方向發現了其他的問題（感謝幸斌提供的思路和疑點），重新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鎖住

10.那么為什么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，進而導致服務掛掉

11.問題到這里有些熟悉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/

12.其實還有一個問題，沒太想明白，為什么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的不了解的以及容易忽略細節的問題還是暴露了出來，其實慢慢的一條線下來也有了一套解決方法的流程和思路，這個是感覺最欣慰的，最后還是要感謝張師傅和幸斌的幫助，和他們討論其實很多時候會把自己從誤區拉回來，也會學到很多的解決問題的思路和方法。