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

時間  2020-07-24
標籤 jdk11 jdk 現存 性能 bug 深度 解析 欄目 Java 简体版
原文   原文鏈接

這是一篇鴿了好久的博客，由於博客內容和素材早就準備差很少了，但就是一直懶得整理，今天終於下定決心終於整理出來了，這也是這個bug JDK-8221393惟一一篇中文介紹博客。html

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

排查過程

做爲一名工程師，面對上面的現象，你會怎麼作？ 我想你的第一反應確定是業務代碼有問題？是否是有什麼地方致使內存泄露？ 是否是業務代碼裏有什麼地方加載的數據太多，愈來愈慢？…… 同事嘗試過dump堆裏的內容，dump jstak線程…… 都沒看出來什麼異常，也優化了業務代碼裏以前一些不合理的邏輯，始終沒有解決問題。 當時的問題是他們都沒有往熱點代碼的方向排查，主要是由於他們不知道有啥好用的工具。 git

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

火焰圖該怎麼讀？

不知道怎麼看火焰圖沒關係，其實很簡單，具體可參考阮一峯老師的如何讀懂火焰圖？。redis

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

你能夠簡單認爲每一塊越寬，它就越耗費CPU，用火焰圖作性能分析的關鍵就是去找那些你以爲本應該很窄但實際卻很寬的函數。上圖中就是咱們有問題服務長期運行後和剛啓動時的生成的火焰圖(一樣的代碼和環境)，左圖明顯有異常，它有好幾個"平頂"，也就是說該函數消耗了過多的CPU，大機率這就是問題的根源了。 apache

這裏我特地找到了該函數調用的堆棧信息，而後就發現了咱們代碼中不合理的地方。api

[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的過程當中產生了性能問題。oracle

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

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

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作清理，因此裏面的數據會愈來愈多，查詢會愈來愈慢。 jvm

問題是用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
相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程