JDK11現存效能bug(JDK-8221393)深度解析

Jack2k發表於2021-09-09
JDK

這是一篇鴿了很久的部落格，因為部落格內容和素材早就準備差不多了，但就是一直懶得整理，今天終於下定決心終於整理出來了，這也是這個bug JDK-8221393唯一一篇中文介紹部落格。

先大致介紹下這個bug，準確說這個應該是jdk11新引入的zgc的一個bug，該bug在被觸發的情況下會導致程式CPU使用率會逐漸升高，如果不管的話最終CPU會到100% 影響服務可用性，而且這個效能bug在jdk11最新的程式碼中仍未修復。不過不用擔心，這個bug觸發的要求比較苛刻，估計這也是jdk開發者不修復該bug的原因之一。另外，我在翻看jdk13原始碼時發現該bug已被修復，並且有些相關設計上的提升。
在這裡插入圖片描述
該bug的表象如上圖，在業務和程式碼邏輯無變更的情況下，CPU使用率大概每隔10天就會翻倍，重啟後恢復正常。上圖中我們分別在11月19和11月29日重啟過，CPU明顯下跌，然後又開啟一輪新的輪迴…… 這個服務是我們很重要的一個服務，我們有同事很長時間都在找原因，也嘗試做過很多優化，一直都沒解決，我們的服務只好靠定期重啟續命了。 不過這事在我介入後的第二天就立馬有了眉目，嘿嘿嘿。。。 (不是我能打，而是他們缺少一把趁手的“兵器”)

排查過程

作為一名工程師，面對上面的現象，你會怎麼做？ 我想你的第一反應肯定是業務程式碼有問題？是不是有什麼地方導致記憶體洩露？ 是不是業務程式碼裡有什麼地方載入的資料太多，越來越慢？…… 同事嘗試過dump堆裡的內容，dump jstak執行緒…… 都沒看出來什麼異常，也優化了業務程式碼裡之前一些不合理的邏輯，始終沒有解決問題。 當時的問題是他們都沒有往熱點程式碼的方向排查，主要是因為他們不知道有啥好用的工具。

而我恰好當時在關注過阿里的Arthas，知道當時正好Arthas新增了效能排查命令profiler 可以生成CPU火焰圖，而我又恰好看過阮一峰老師的如何讀懂火焰圖？。然後我就給同事推薦了Arthas並建議同事用Arthas生成CPU的火焰圖，看下到底是哪個地方耗費CPU，然後就發現了異常。
在這裡插入圖片描述

火焰圖該怎麼讀？

不知道怎麼看火焰圖不要緊，其實很簡單，具體可參考阮一峰老師的如何讀懂火焰圖？。

y 軸表示呼叫棧，每一層都是一個函式。呼叫棧越深，火焰就越高，頂部就是正在執行的函式，下方都是它的父函式。
x 軸表示抽樣數，如果一個函式在 x 軸佔據的寬度越寬，就表示它被抽到的次數多，即執行的時間長。注意，x 軸不代表時間，而是所有的呼叫棧合併後，按字母順序排列的。
火焰圖就是看頂層的哪個函式佔據的寬度最大。只要有"平頂"（plateaus），就表示該函式可能存在效能問題。

你可以簡單認為每一塊越寬，它就越耗費CPU，用火焰圖做效能分析的關鍵就是去找那些你覺得本應該很窄但實際卻很寬的函式。上圖中就是我們有問題服務長期執行後和剛啟動時的生成的火焰圖(同樣的程式碼和環境)，左圖明顯有異常，它有好幾個"平頂"，也就是說該函式消耗了過多的CPU，大概率這就是問題的根源了。

這裡我特意找到了該函式呼叫的堆疊資訊，然後就發現了我們程式碼中不合理的地方。

[0x00007f2091c15000]
   java.lang.Thread.State: RUNNABLE
    at java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames(java.base@11/Native Method)
    at java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames(java.base@11/StackStreamFactory.java:386)
    at java.lang.StackStreamFactory$AbstractStackWalker.getNextBatch(java.base@11/StackStreamFactory.java:322)
    at java.lang.StackStreamFactory$AbstractStackWalker.peekFrame(java.base@11/StackStreamFactory.java:263)
    at java.lang.StackStreamFactory$AbstractStackWalker.hasNext(java.base@11/StackStreamFactory.java:351)
    at java.lang.StackStreamFactory$StackFrameTraverser.tryAdvance(java.base@11/StackStreamFactory.java:593)
    at java.util.stream.ReferencePipeline.forEachWithCancel(java.base@11/ReferencePipeline.java:127)
    at java.util.stream.AbstractPipeline.copyIntoWithCancel(java.base@11/AbstractPipeline.java:502)
    at java.util.stream.AbstractPipeline.copyInto(java.base@11/AbstractPipeline.java:488)
    at java.util.stream.AbstractPipeline.wrapAndCopyInto(java.base@11/AbstractPipeline.java:474)
    at java.util.stream.FindOps$FindOp.evaluateSequential(java.base@11/FindOps.java:150)
    at java.util.stream.AbstractPipeline.evaluate(java.base@11/AbstractPipeline.java:234)
    at java.util.stream.ReferencePipeline.findFirst(java.base@11/ReferencePipeline.java:543)
    at org.apache.logging.log4j.util.StackLocator.lambda$getCallerClass$6(StackLocator.java:54)
    at org.apache.logging.log4j.util.StackLocator$$Lambda$94/0x00007f238e2cacb0.apply(Unknown Source)
    at java.lang.StackStreamFactory$StackFrameTraverser.consumeFrames(java.base@11/StackStreamFactory.java:534)
    at java.lang.StackStreamFactory$AbstractStackWalker.doStackWalk(java.base@11/StackStreamFactory.java:306)
    at java.lang.StackStreamFactory$AbstractStackWalker.callStackWalk(java.base@11/Native Method)
    at java.lang.StackStreamFactory$AbstractStackWalker.beginStackWalk(java.base@11/StackStreamFactory.java:370)
    at java.lang.StackStreamFactory$AbstractStackWalker.walk(java.base@11/StackStreamFactory.java:243)
    at java.lang.StackWalker.walk(java.base@11/StackWalker.java:498)
    at org.apache.logging.log4j.util.StackLocator.getCallerClass(StackLocator.java:53)
    at org.apache.logging.log4j.util.StackLocatorUtil.getCallerClass(StackLocatorUtil.java:61)
    at org.apache.logging.slf4j.Log4jLoggerFactory.getContext(Log4jLoggerFactory.java:43)
    at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:46)
    at org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:29)
    at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:358)
    at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:383)
    at com.xxxxxxx.infra.cache.redis.ReadCommandTemplate.<init>(ReadCommandTemplate.java:21)
    at com.xxxxxxx.infra.cache.redis.RedisClient$4.<init>(RedisClient.java:138)
    at com.xxxxxxx.infra.cache.redis.RedisClient.hget(RedisClient.java:138)
    ...
    ...

ReadCommandTemplate是我們公司封裝的一個redis client，每讀寫一次redis就會例項化一個ReadCommandTemplate，我們的業務邏輯中每個請求都會讀一次redis，所以導致ReadCommandTemplate這個類生成很多個例項。本身這個類很輕量，按理來說多次例項話也沒關係，但其中用了logger，而且logger沒有宣告為static，所以沒new 一個ReadCommandTemplate，都會同時生成一個logger，從火焰圖來看，似乎是生成logger的過程中產生了效能問題。

public abstract class ReadCommandTemplate<T> {
    private Logger logger = LoggerFactory.getLogger(ReadCommandTemplate.class);
    /** 
     * 其他程式碼邏輯省略
     */
}

有經驗的java開發者一眼就能看出來上面程式碼的不合理之處，但應該只是稍微影響效能，不會出現文首那種詭異的現象！ 確實，這個redis client在我們部分被廣泛使用，其他的應用都沒出現問題。。。 會不會是這個應用恰巧湊齊了某個bug觸發的所有條件？？

Bug的確認

要想確認bug是否是這個非static的logger導致的，有兩個方案：1. 修復logger的問題，看CPU是否會上漲。 2. 真正搞清楚這個bug的原理。因為方案1需要至少等待一週才能實錘，所以我們選擇了二者並行。同事修復了logger，而我開啟了問題探索和jvm原始碼閱讀之旅。後來方案1確實也正式了是logger導致的，而我也找到了19年有人給jvm團隊反饋bug後jvm團隊討論的郵件列表。
在這裡插入圖片描述
jdk的開發者Stefan Karlsson確認並大致給出了這個bug出現的原因，如上圖。這裡我大致解釋下，JVM在查詢方法的時候會呼叫"ResolvedMethodTable::lookup"，其實這裡是查詢一個只有1007個bucket的hash表，因為jdk11的zgc沒有定期對ResolvedMethodTable做清理，所以裡面的資料會越來越多，查詢會越來越慢。

問題是用jdk11+zgc+log4j組合的人也非常多，為什麼偏偏就我們的程式碼觸發了bug？？

深度剖析

為了深入理解這個bug，我們首先來看下我們調LoggerFactory.getLogger()的時候發生了什麼！！
在這裡插入圖片描述
在jdk9及以後的版本中，log4j使用了新的StackWalker來獲取執行緒的堆疊資訊，然後遍歷每個棧幀，所以StackWalker就呼叫native方法fetchStackFrames從JVM裡獲取這個棧幀。

我翻閱了JVM程式碼，找到了ResolvedMethodTable::lockup()在做啥！ 不過首先我們得知道ResolvedMethodTable是啥？ ResolvedMethodTable可以簡單認為是JVM中儲存所有已經解析到的方法資訊的一個hashtable，它只有1007的bucket(為什麼設計這麼小？)，這麼小的bucket必然很容易產生hash衝突，處理hash衝突的方式就是開鏈，而lockup()在查詢過程中，需要遍歷單連結串列，所以如果單連結串列過長，lookup的查詢效能就下來了，lookup()的原始碼如下。

oop ResolvedMethodTable::lookup(Method* method) {
  unsigned int hash = compute_hash(method);
  int index = hash_to_index(hash);
  return lookup(index, hash, method);
}
oop ResolvedMethodTable::lookup(int index, unsigned int hash, Method* method) {
  for (ResolvedMethodEntry* p = bucket(index); p != NULL; p = p->next()) {
    if (p->hash() == hash) {
      oop target = p->object_no_keepalive();
      if (target != NULL && java_lang_invoke_ResolvedMethodName::vmtarget(target) == method) {
        ResourceMark rm;
        log_debug(membername, table) ("ResolvedMethod entry found for %s index %d",
                                       method->name_and_sig_as_C_string(), index);
        return p->object();
      }
    }
  }
  return NULL;
}

現在的問題是究竟是什麼導致ResolvedMethodTable資料太多，從而使得其中單個bucket的連結串列過長？ 我們還是從該bug的郵件討論列表裡找到答案http://mail.openjdk.java.net/pipermail/zgc-dev/2019-March/000612.html，這裡我大概翻譯如下:

GC除了解除安裝不用的類時，也會做好多其他的清理工作，比如清理ResolvedMethodTable和StringTable中不用的資訊。ResolvedMethodTable儲存著java中ResolvedMethodName類例項的弱指標，如果ResolvedMethodName不可達，正常情況下gc就會清理掉這個不可達物件。而ResolvedMethodName是MemberName中的一部分。StackWalker遍歷棧幀的時候，就會建立MemberName java物件並放到StackFrameInfo.memberName中，jvm中的程式碼實現如下:

void java_lang_StackFrameInfo::set_method_and_bci(Handle stackFrame, 
const methodHandle& method, int bci, TRAPS) {
...
   // 建立ResolvedMethodName物件並插入到ResolvedMethodTable中
   CallInfo info(method(), ik, CHECK);
   // 把ResolveMethodName物件放到MemberName中
   MethodHandles::init_method_MemberName(mname, info);

堆疊呼叫資訊如下：

  java_lang_StackFrameInfo::set_method_and_bci(Handle, methodHandle 
const&, int, Thread*)
  JavaFrameStream::fill_frame(int, objArrayHandle, methodHandle const&, 
Thread*)
  StackWalk::fill_in_frames(long, BaseFrameStream&, int, int, 
objArrayHandle, int&, Thread*)
  StackWalk::fetchNextBatch(Handle, long, long, int, int, 
objArrayHandle, Thread*)
  JVM_MoreStackWalk
  java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames

後續，如果StackFrameInfos不用之後，這些物件會被從類的引用關係中移除，並被gc回收掉，然後gc會移除ResolvedMethodTable中相應的ResolvedMethodName。但問題是jdk11中，zgc並沒有真正移除這些ResolvedMethodName，從而導致ResolvedMethodTable中的資料量越來越大，單鏈越來越長，查詢效率越來越低。
在這裡插入圖片描述
在JDK11的原始碼中SymbolTable::unlink()中實現了ResolvedMethodTable中無用資訊的解除安裝，其他幾個老gc都呼叫了，而zgc中確實沒有呼叫，不知道這是忘記了還是特意為之……

簡單梳理下就是：每次呼叫StackWalker遍歷棧幀的時候，每個棧幀都會生成一個ResolvedMethodName物件放到jvm中的ResolvedMethodTable中，但jdk11的zgc不能有效清理其中不用的物件。因為ResolvedMethodTable是個定容的hashtable，隨著其中的資料越來越多，每個bucket的單連結串列越來越長，查詢效率會越來越慢。 所以最終導致CPU的使用率越來越高。

避坑指南

如果你看懂了上文的bug原理，相信你已經知道了如何閉坑，如果沒看懂也沒關係， 一句話 不要使用jdk11+zgc的同時頻繁使用StackWalker(比如錯誤使用log4j)。當然也不是完全不能使用log4j了，只要不是頻繁呼叫StackWalker就沒問題，像我們程式碼中的logger只需要宣告成static，這樣StackWalker只會在類初始化的時候呼叫，就不會有問題了。知道了原理，也就能解釋清楚為什麼我們很多其他應用用了jdk11也用了有問題的RedisClient沒有出現cpu異常的現象，就是因為其他應用沒有啟用zgc。

當然這個bug的本質就是jdk11+zgc+StackWalker的bug，三者都是bug觸發的必要條件，如果你能避免其中一條就可以完美避開這個bug了，比如升級到jdk12+，比如不用zgc……

Bugfix

對於我們應用來說，只需按照上面的避坑指南操作即可，但對於jdk團隊來說，這個bug他們肯定是要修復的。
在這裡插入圖片描述
從官網bug頁面可以看到這個bug在jdk13中已經修復了，我們來看看他們是如何修復的。是不是隻需要在zgc合適的地方調一下SymbolTable::unlink()就行了？是的，但jdk團隊做的遠不止於此，除了unlink之外，他們還優化了ResolvedMethodTable的實現，支援了動態擴縮容，可以避免單連結串列過長的問題，具體可以看下jdk原始碼中src/hotspot/share/prims/resolvedMethodTable.cpp的檔案。

void ResolvedMethodTable::do_concurrent_work(JavaThread* jt) {
  _has_work = false;
  double load_factor = get_load_factor();
  log_debug(membername, table)("Concurrent work, live factor: %g", load_factor);
  // 人工load_factor大於2，並且沒有達到最大限制，就執行bucket擴容，並且移除無用的entry
  if (load_factor > PREF_AVG_LIST_LEN && !_local_table->is_max_size_reached()) {
    grow(jt);
  } else {
    clean_dead_entries(jt);
  }
}

void ResolvedMethodTable::grow(JavaThread* jt) {
  ResolvedMethodTableHash::GrowTask gt(_local_table);
  if (!gt.prepare(jt)) {
    return;
  }
  log_trace(membername, table)("Started to grow");
  {
    TraceTime timer("Grow", TRACETIME_LOG(Debug, membername, table, perf));
    while (gt.do_task(jt)) {
      gt.pause(jt);
      {
        ThreadBlockInVM tbivm(jt);
      }
      gt.cont(jt);
    }
  }
  gt.done(jt);
  _current_size = table_size();
  log_info(membername, table)("Grown to size:" SIZE_FORMAT, _current_size);
}

總結

這個bug觸發的主要原因其實還是我們自己的程式碼寫的不夠規範(logger未宣告為static)，而這個不規範其實也對其他沒有觸發這個bug的應用也產生了影響，畢竟生成logger也是會消耗效能的，我們程式碼fix後其他應用升級，有些服務CPU佔用率降低5%+。這也充分說明程式碼質量的重要性，尤其是那種被廣泛採用的基礎程式碼。

另外是不是有些人還有個疑問，這個bug為什麼不在jdk11後續版本中修掉，而是選擇在jdk13中徹底修掉，不怕影響到使用jdk11的使用者嗎？對這個問題我有個想法，其實這個bug並不是很容易觸發的嚴重bug(jdk11+zgc+log4j的頻繁呼叫)，而且即便是觸發了，jdk的使用者也很容易通過修改自己的程式碼來規避這個bug，所以對jdk的開發者而言這不是一個重要且緊急的bug，後續修復掉就行了。

參考資料

  1. 阿里巴巴開源java問題排查工具 Arthas.
  2. 阮一峰 如何讀懂火焰圖？
  3. jdk開發者關於bug討論的郵件列表
本文來自https://blog.csdn.net/xindoo

相關文章