JDK11现存性能bugJDK8221393深度解析

3次阅读

共计 9511 个字符，预计需要花费 24 分钟才能阅读完成。

这是一篇鸽了很久的博客，因为博客内容和素材早就筹备差不多了，但就是始终懒得整顿，明天终于下定决心终于整理出来了，这也是这个 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 是否是这个非 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……

对于咱们利用来说，只需依照下面的避坑指南操作即可，但对于 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，后续修复掉就行了。