JDK11现存性能bugJDK8221393深度解析

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