作者：vivo 網際網路伺服器團隊- Jiang Ye

本文詳細的記錄了一次0點介面嚴重超時的問題排查經歷。本文以作者自身視角極具代入感的描繪了從問題定位到具體的問題排查過程，並透過根因分析並最終解決問題。整個過程需要清晰的問題排查思路和豐富的問題處理經驗，也離不開公司強大的呼叫鏈、和全方位的系統監控等基礎設施。

一、問題發現

我所負責的商城活動系統用於承接公司線上官方商城的營銷活動，最近突然收到凌晨0點的服務超時告警。

營銷活動類的系統有如下 特點：

1. 營銷活動一般會0點開始，如紅包雨、大額優惠券搶券等。

2. 日常營銷活動的機會重新整理，如每日任務，每日簽到，每日抽獎機會的重新整理等。

營銷活動的利益刺激會吸引大量真實使用者及黑產前來參與活動，所以流量在0點會迎來一波小高峰，也正因如此線上偶現的服務超時告警起初並未引起我的注意。但是接下來的幾天，每天的凌晨0點都會收到服務超時告警，這引起了我的警惕，決定一探究竟。

二、問題排查

首先透過公司的應用監控系統檢視了0點前後每分鐘各介面的P95響應時間。如下圖所示，介面響應時間在0點時刻最高達到了8s。繼續檢視鎖定耗時最高的介面為商品列表介面，下面就針對這個介面展開具體的排查。

2.1 排查思路

正式排查之前，先和大家分享下我對介面超時問題的排查思路。下圖是一個簡化的請求流程。

1. 使用者嚮應用發起請求

2. 應用服務進行邏輯處理

3. 應用服務透過RPC呼叫下游應用以及進行資料庫的讀寫操作

服務超時可能是應用服務自身慢導致，也可能下游依賴響應慢導致。具體排查思路如下：

2.1.1 下游依賴慢服務排查

（1）透過呼叫鏈技術定位下游依賴中的慢服務

呼叫鏈技術是實現系統可觀測性的重要保障，常見的開源方案有ziplin、pinpoint等。完整的呼叫鏈可以按時間正序記錄每一次下游依賴呼叫的耗時，如rpc服務呼叫、sql執行耗時、redis訪問耗時等。因此使用呼叫鏈技術可以迅速定位到下游依賴的慢服務，如dubbo介面訪問超時、慢SQL等。但理想很豐滿，現實很骨感。由於呼叫鏈路資訊的數量過大，想要收集全量的鏈路資訊需要較高的儲存成本和計算資源。因此在技術落地時，通常都會採用抽樣的策略來收集鏈路資訊。抽樣帶來的問題是請求鏈路資訊的丟失或不完整。

（2）無呼叫鏈時的慢服務排查

如果呼叫鏈丟失或不完整，我們就要再結合其它手段進行綜合定位了。

下游RPC服務響應超時：如果是用Dubbo框架，在provider響應超時時會列印timeout相關日誌；如果公司提供應用監控，還可以檢視下游服務P95響應時間綜合判斷。

慢SQL：MySQL支援設定慢SQL閾值，超過該閾值會記錄下慢SQL；像我們常用的資料庫連線池Druid也可以透過配置列印慢SQL日誌。如果確認請求鏈路中存在慢SQL可以進一步分析該SQL的執行計劃，如果執行計劃也沒有問題，再去確認在慢SQL產生時mysql主機的系統負載。

下游依賴包含Redis、ES、Mongo等儲存服務時，慢服務的排查思路和慢SQL排查相似，在此不再贅述。

2.1.2 應用自身問題排查

（1）應用邏輯耗時多

應用邏輯耗時多比較常見，比如大量物件的序列化和反序列化，大量的反射應用等。這類問題的排查通常要從分析原始碼入手，編碼時應該儘量避免。

（2）垃圾回收導致的停頓（stop the world）

垃圾回收會導致應用的停頓，特別是發生Old GC或Full GC時，停頓明顯。不過也要看應用選配的垃圾回收器和垃圾回收相關的配合，像CMS垃圾回收器通常可以保證較短的時間停頓，而Parallel Scavenge垃圾回收器則是追求更高的吞吐量，停頓時間會相對長一些。

透過JVM啟動引數-XX:+PrintGCDetails，我們可以列印詳細的GC日誌，藉此可以觀察到GC的型別、頻次和耗時。

（3）執行緒同步阻塞

執行緒同步，如果當前持有鎖的執行緒長時間持有鎖，排隊的執行緒將一直處於blocked狀態，造成服務響應超時。可以透過jstack工具列印執行緒堆疊，查詢是否有處於block狀態的執行緒。當然jstack工具只能採集實時的執行緒堆疊資訊，如果想要檢視歷史堆疊資訊一般需要透過Prometheus進行收集處理。

2.2 排查過程

下面按照這個排查思路進行排查。

2.2.1 下游依賴慢服務排查

（1）透過呼叫鏈檢視下游慢服務

首先到公司的應用監控平臺上，篩選出0點前後5min的呼叫鏈列表，然後按照鏈路耗時逆序排列，發現最大介面耗時7399ms。檢視呼叫鏈詳情，發現下游依賴耗時都是ms級別。呼叫鏈因為是抽樣採集，可能存在鏈路資訊丟失的情況，因此需要其他手段進一步排查下游依賴服務。

（2）透過其他手段排查下游慢服務

接著我檢視了0點前後的系統日誌，並沒有發現dubbo呼叫超時的情況。然後透過公司的應用監控檢視下游應用P95響應時間，如下圖，在0點時刻，下游的一些服務響應時長確實會慢一些，最高的達到了1.45s，雖然對上游有一定影響，但不至於影響這麼大。

（3）慢SQL排查

接下來是慢SQL的排查，我們系統的連線池使用的是阿里開源的druid，SQL執行超過1s會列印慢SQL日誌，檢視日誌中心也沒有發現慢SQL的蹤跡。

到現在，可以初步排除因下游依賴慢導致服務超時，我們繼續排查應用自身問題。

2.2.2 應用自身問題排查

（1）複雜耗時邏輯排查

首先檢視了介面的原始碼，整體邏輯比較簡單，透過dubbo呼叫下游商品系統獲取商品資訊，本地再進行商品資訊的排序等簡單的處理。不存在複雜耗時邏輯問題。

（2）垃圾回收停頓排查

透過公司應用監控檢視應用的GC情況，發現0點前後沒有發生過full GC，也沒有發生過Old GC。垃圾回收停頓的因素也被排除。

（3）執行緒同步阻塞排查

透過公司應用監控檢視是否存在同步阻塞執行緒，如下圖：

看到這裡，終於有種天不負有心人的感覺了。從00:00:00開始一直到00:02:00，這兩分鐘裡，出現了較多狀態為BLOCKED的執行緒， 超時的介面大機率和這些blocked執行緒相關。我們只需要進一步分析JVM堆疊資訊即可真相大白。

我們隨機選取一臺比較有代表性的機器檢視block堆疊資訊，堆疊採集時間是2022-08-02 00:00:20。

// 日誌列印操作，被執行緒catalina-exec-408阻塞
"catalina-exec-99" Id=506 BLOCKED on org.apache.log4j.spi.RootLogger@15f368fa owned by "catalina-exec-408" Id=55204
    at org.apache.log4j.Category.callAppenders(Category.java:204)
    -  blocked on org.apache.log4j.spi.RootLogger@15f368fa
    at org.apache.log4j.Category.forcedLog$original$mp4HwCYF(Category.java:391)
    at org.apache.log4j.Category.forcedLog$original$mp4HwCYF$accessor$pRDvBPqB(Category.java)
    at org.apache.log4j.Category$auxiliary$JhXHxvpc.call(Unknown Source)
    at com.vivo.internet.trace.agent.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:46)
    at org.apache.log4j.Category.forcedLog(Category.java)
    at org.apache.log4j.Category.log(Category.java:856)
    at org.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:324)
    ...
 
// 日誌列印操作，被執行緒catalina-exec-408阻塞
"catalina-exec-440" Id=55236 BLOCKED on org.apache.log4j.spi.RootLogger@15f368fa owned by "catalina-exec-408" Id=55204
    at org.apache.log4j.Category.callAppenders(Category.java:204)
    -  blocked on org.apache.log4j.spi.RootLogger@15f368fa
    at org.apache.log4j.Category.forcedLog$original$mp4HwCYF(Category.java:391)
    at org.apache.log4j.Category.forcedLog$original$mp4HwCYF$accessor$pRDvBPqB(Category.java)
    at org.apache.log4j.Category$auxiliary$JhXHxvpc.call(Unknown Source)
    at com.vivo.internet.trace.agent.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:46)
    at org.apache.log4j.Category.forcedLog(Category.java)
    at org.apache.log4j.Category.log(Category.java:856)
    at org.slf4j.impl.Log4jLoggerAdapter.warn(Log4jLoggerAdapter.java:444)
    ...
 
// 日誌列印操作，被執行緒catalina-exec-408阻塞
"catalina-exec-416" Id=55212 BLOCKED on org.apache.log4j.spi.RootLogger@15f368fa owned by "catalina-exec-408" Id=55204
    at org.apache.log4j.Category.callAppenders(Category.java:204)
    -  blocked on org.apache.log4j.spi.RootLogger@15f368fa
    at org.apache.log4j.Category.forcedLog$original$mp4HwCYF(Category.java:391)
    at org.apache.log4j.Category.forcedLog$original$mp4HwCYF$accessor$pRDvBPqB(Category.java)
    at org.apache.log4j.Category$auxiliary$JhXHxvpc.call(Unknown Source)
    at com.vivo.internet.trace.agent.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:46)
    at org.apache.log4j.Category.forcedLog(Category.java)
    at org.apache.log4j.Category.log(Category.java:856)
    at org.slf4j.impl.Log4jLoggerAdapter.warn(Log4jLoggerAdapter.java:444)
    ...

透過堆疊資訊可以分析出2點：

1. 處於blocked狀態的執行緒都是日誌列印

2. 所有的執行緒都是被執行緒名為“catalina-exec-408”阻塞

追蹤到這裡，慢服務的表層原因就清楚了。被執行緒catalina-exec-408阻塞的執行緒，一直處於blocked狀態，導致服務響應超時。

三、根因分析

表層原因找到以後，我們一起撥開層層迷霧，尋找真相背後的真相吧！

所有慢服務的執行緒都是在列印日誌的時候被執行緒catalina-exec-408阻塞。那麼執行緒catalina-exec-408在做什麼呢？

可以發現，在00:00:18.858時刻，該執行緒在列印登入態校驗失敗的日誌，也並無複雜的處理邏輯。難道是該執行緒列印日誌慢，阻塞了其他執行緒嗎？帶著這個疑問，我開始深入日誌框架的原始碼尋找答案。

我們的專案使用的日誌框架是slf4j + log4j。根據被阻塞的執行緒棧資訊我們定位到這段程式碼如下：

public
void callAppenders(LoggingEvent event) {
  int writes = 0;
 
  for(Category c = this; c != null; c=c.parent) {
    // Protected against simultaneous call to addAppender, removeAppender,...
    // 這是204行，加了sychronized
    synchronized(c) {
  if(c.aai != null) {
    writes += c.aai.appendLoopOnAppenders(event);
  }
  if(!c.additive) {
    break;
  }
    }
  }
 
  if(writes == 0) {
    repository.emitNoAppenderWarning(this);
  }
}

可以看到堆疊資訊中的204行是synchronized程式碼塊，對其它執行緒造成阻塞的這是這塊程式碼。那麼synchronized程式碼塊內部邏輯是什麼呢？為什麼要執行很久呢？下面是synchronized程式碼塊中的核心邏輯：

public
  int appendLoopOnAppenders(LoggingEvent event) {
    int size = 0;
    Appender appender;
 
    if(appenderList != null) {
      size = appenderList.size();
      for(int i = 0; i < size; i++) {
    appender = (Appender) appenderList.elementAt(i);
    appender.doAppend(event);
      }
    }   
    return size;
  }

可以看到，這塊邏輯就是將日誌寫入所有配置的appender中。我們配置的appender有兩個，一個是console appender，也就是輸出到catalina.out檔案。還有一個是按照公司日誌中心採集要求，以Json格式輸出的appender。這裡可以做出推斷，執行緒catalina-exec-408在將日誌輸出到appender時耗時較多。

我很自然的開始懷疑當時的機器負載，特別是IO負載可能會比較高，透過公司的機器監控，我們檢視了下相關指標：

果然，從00:00:00開始，磁碟IO消耗持續彪高，到1分鐘20秒第一波高峰才結束，在00:00:20時刻，IO消耗達到峰值99.63%,接近100%。難怪應用輸出一條日誌都這麼難！

到底是誰把IO資源消耗光了，消耗到幾乎骨頭都不剩？帶著疑問，我進一步透過公司的機器監控檢視了主機快照：

發現在00:00:20時刻，tomcat使用者在執行指令碼/bin/sh /scripts/cutlog.sh，指令碼在執行命令cp catalina.out catalina.out-2022-08-02-00。IO消耗達到了109475612 bytes/s(約104MB/s) 。

事情就要水落石出了，我們繼續掘地三尺。運維同學登陸到機器上，切換到tomcat使用者，檢視定時任務列表（執行crontab -l），得到結果如下：

00 00 * * * /bin/sh /scripts/cutlog.sh

正是快照中的指令碼/bin/sh /scripts/cutlog.sh，每天0點執行。具體的指令碼內容如下：

$ cat /scripts/cutlog.sh
#!/bin/bash
files=(
  xxx
)
 
time=$(date +%F-%H)
 
for file in ${files[@]}
do
  dir=$(dirname ${file})
  filename=$(echo "xxx"|awk -F'/' '{print $NF}')
  # 歸檔catalina.out日誌並清空catalina.out當前檔案內容
  cd ${dir} && cp ${filename} ${filename}-${time} && > ${filename}
done

我們從指令碼中找到了高IO消耗的元兇，就是這個copy命令，目的是將catalina.out日誌歸檔並將catalina.out日誌檔案清空。

這個正常的運維指令碼肯定是比較消耗 IO 資源的，執行的時長受檔案大小影響。運維同學也幫忙看了下歸檔的日誌大小：

[root@xxx:logdir]

# du -sh *

1.4G catalina.out

2.6G catalina.out-2022-08-02-00

歸檔的檔案大小有2.6 G，按照104MB/s估算，需要耗時25秒。 也就是00:00:00到00:00:25期間，業務日誌輸出都會比較緩慢，造成大量執行緒block，進而導致介面響應超時。

四、問題解決

定位到了問題的根因，就可以對症下藥了。有幾個方案可以選擇：

4.1 生產環境不列印日誌到console

消耗 IO資源的操作就是catalina.out日誌的歸檔，如果不寫日誌到該檔案，是可以解決日誌列印IO等待的問題的。但是像本地除錯、壓測環境還是比較依賴console日誌的，所以就需要根據不同環境來設定不同的console appender。目前logback、Log4j2已經支援根據Spring profile來區別配置，我們用的Log4j還不支援。切換日誌底層框架的成本也比較高，另外早期的公司中介軟體與Log4j日誌框架強耦合，無法簡單切換，所以我們並沒有採用這個方案。

4.2 配置日誌非同步列印

Log4j提供了AsyncAppender用於支援非同步日誌列印，非同步日誌可以解決同步日誌列印IO等待的問題，不會阻塞業務執行緒。

非同步日誌的副作用：

非同步日誌是在日誌列印時，將event加入到buffer佇列中，buffer的大小預設是128，支援配置。關於buffer滿了後有兩種處理策略。

（1）阻塞

當屬性blocking設定為true時，使用阻塞策略，預設是true。即buffer滿了後，同步等待，此時執行緒會阻塞，退變成同步日誌。

（2）丟棄

如果blocking設定為false，在buffer滿了以後，會將該條日誌丟棄。

4.3 最終方案

最終我們選擇了方案2，即配置日誌非同步列印。buffer佇列大小設定2048，考慮到部分日誌丟失在業務上是可以接受的，因此犧牲了小部分可靠性換區更高的程式效能，將blocking設定為false。

4.4 小結

這次的問題排查經歷，我收穫了幾點感悟，和大家分享一下：

1）要對線上告警保持敬畏之心

我們應該敬畏每一個線上告警，重視每一條錯誤日誌。現實情況是大多數時候告警只是因為網路抖動，短暫的突發流量等，是可以自行恢復的，這就像狼來了的故事一樣，讓我們放鬆了警惕，導致我們可能會錯過真正的問題，給系統帶來嚴重災難，給業務帶來損失。

2）刨根問底

告警只是表象，我們需要搞清楚每個告警的表面原因和根本原因。比如這次的介面超時告警，只有分析出”copy檔案耗盡磁碟IO，導致日誌列印執行緒block“這個根本原因後，才能給出優雅合理的解決方案。說起來簡單，實操起來可能會遇到很多困難，這要求我們有清晰的問題排查思路，有良好的的系統可觀測性建設，有紮實的技術基本功和不找到”真兇“永不放棄的決心。

最後希望我的這次問題排查經歷能夠讓你有所收穫，有所啟發。我也將本文用到的超時問題排查思路整理成了流程圖，供大家參考。你有遇到過哪些線上故障呢？你的排查思路是怎樣的呢？歡迎留言交流討論。