一次線上死循環的排查過程

場景

• A寫了一個服務，給B調用

• A的這個服務針對一個key，在一次調用完成以前不能調用第二次，若是連續調用，第二次不會執行業務，而是直接返回系統繁忙，使用ConcurrentHashMap + Atomic的cas控制。（不要吐槽咱們小公司小用戶量暫時沒有使用水平擴展的分佈式服務哦，這裏就考慮了單機線程安全）

  // {key -> 是否正在運算}
  Map<Long, AtomicBoolean> map = new ConcurrentHashMap<>();
  
  public * *(@RequestBody ..)  {
      //..省略校驗和獲取主鍵
      // 可以保證單機線程安全
      AtomicBoolean atomicBoolean = map.computeIfAbsent(key, (key)->new AtomicBoolean(false));
      // 若是正在執行，直接返回一下子再來
      if(!atomicBoolean.compareAndSet(false, true)){
          return "系統繁忙";
      }
      try {
          //..業務操做並返回
      }finally {
          atomicBoolean.set(false);
      }
  }
  複製代碼

某日，調用方B看了日誌，有一個key調用這個服務後一直返回系統繁忙，且沒再成功過，因而，開始了排查過程。

過程

調用方日誌

首先，先看調用方B的日誌，找到了使用這個key第一次失敗調用的位置：

20-06-06 12:09:12 INFO  ** - 開始調用某key
20-06-06 12:09:22 ERROR ** - 調用 fail :
java.net.http.HttpTimeoutException: request timed out
複製代碼

能夠看出使用了Http調用，從開始調用到失敗日誌，有10s時間，正是請求超時時間。

請求沒返回，以後調用過程一直返回系統繁忙，說明一直沒有執行到上面的釋放cas鎖的塊：

try {
    //..業務操做並返回
}finally {
    // 沒有執行到
    atomicBoolean.set(false);
}
複製代碼

基本猜到了問題，業務操做代碼中一直沒有執行完畢；

服務方日誌

再去看了服務方A的日誌：

20-06-06 12:09:13.476 INFO  ** - 結束
// 關鍵，有一個只有開始沒有結束
20-06-06 12:09:13.476 INFO  ** - 開始
// 這個開始是其它key的
20-06-06 12:09:23.267 INFO  ** - 開始
複製代碼

果真，在12:09:13的一次調用只有開始，沒有結束。

進程

再去看了服務A的服務器進程線程運行情況：

top
top -Hp <pid>
複製代碼

發現有一個線程已經佔用了將近43分鐘的CPU時間，而距離最後一次調用大約過去了一個小時時間，可見極可能是A的業務代碼裏面有死循環致使這個線程一直處於運行狀態。

由於這個線上只是用了jre，沒有jdk，沒有jstack命令能夠查看詳細的線程信息，至於爲何沒有，得問A。

// 假想一下咱們執行了jstack 線程id查看到了確實這個線程一直處於運行狀態
jstack <pid>
複製代碼

問題

看了看業務代碼，定位到了下面一個循環，A爲了分批保存大量數據，使用了一個while循環，線下測試時沒有達到須要分批保存的閾值，而最後到了線上，須要分批保存，flg沒有像預想的那樣退出循環，致使一直插入數據。

while (flg){
    flg = false;
    if(..){
        testService.save(..);
        if(..)
	        flg = true;
    }
}


複製代碼

看到這裏，我猜測既然while循環中插入數據，那麼數據庫中這個表估計這一個小時已經被插入了許多重複數據了，可是取數據庫裏一刷新，居然沒有明顯新增：

猜測了一下，是由於事務一直在這裏循環，未提交，因此我去其它mysql鏈接會話中固然不可見未提交事務中的記錄，可是爲了更加確認，決定去查如下數據庫表文件，發現這個只有八百多條記錄的表居然已經以下佔用了700M左右的數據，因此，雖然事務未提交，可是它的表文件是在不停增長的。

並且，刷新以後發現，這個表文件的更改時間一直變化，至此證實了死循環問題代碼的存在性。

解決

其實A的分批插入想法能夠比較可靠的使用reactor中流的一個buffer方法實現：

Flux.fromIterable(list)
    .buffer(savePerNum)
    .subscribe(testService::save);
複製代碼

避免了使用死循環，且可讀性更加的高。

發佈以後，問題解決。

總結

• 單機狀況下，對須要控制線程安全的資源能夠使用ConcurrentHashMap + Atomic~ + cas控制
• 出現問題要分析日誌，找到問題出現的關鍵位置，觀察猜測問題的可能緣由
• 查看java進程和線程信息證實猜測
• 若是事務沒有提交，表文件仍是會不停改變增大的，雖然其它會話看不到未提交的數據
• 流式的分批插入能夠使用reactor的buffer優雅完成

小夥伴們有什麼建議和想法，歡迎討論啊~