一次 ES-APM 导致的概率性大量线程阻塞问题排查

前段时间我们接入了 ELK 公司出品的 Elastic-APM 作为全链路监控平台 , 终结了我好几年前撸的字节码注入全链路监控平台 。 前段时间有一个业务在启动过程中 , 会概率性出现大量线程阻塞 , 导致可对外提供服务的 HTTP 线程非常少 , 流量进来以后马上出现 HTTP 线程耗尽 , 健康检查接口请求失败 , 服务被 k8s 杀死 。
一次 ES-APM 导致的概率性大量线程阻塞问题排查文章插图
堆栈分析既然是线程的问题 , 当然想到的是 dump 线程堆栈 , 人肉阅读也可以 , 上传到 PerfMa XSheepdog 会更加简单 。 在锁的这一栏的截图如下所示 。
一次 ES-APM 导致的概率性大量线程阻塞问题排查文章插图
可以看到 http-nio-18880-exec-44 线程持有了一个锁 , 这个锁被其它的 199 个线程等待 。 持有锁的线程堆栈如下图所示 。
一次 ES-APM 导致的概率性大量线程阻塞问题排查文章插图
上层的调用方法是 co.elastic.apm.agent.bci.ElasticApmAgent#ensureInstrumented , 这段逻辑背后是在调用 bytebuddy 利用 ASM 进行 class 的转换注入 。
等待锁的线程恰好 block 也在这个方法 , 如下图所示 。
一次 ES-APM 导致的概率性大量线程阻塞问题排查文章插图
通过堆栈分析 , 这个问题的出现与我们业务代码用了 ParallelStream 有关 。 Java 中的 Stream 是一个比较好用的东西 , 在函数式编程、流式数据处理上写起来比较简单 。 除了串行化的流式处理 , Java 也提供了并行流 parallelStream 可以使用多核多线程并行处理 , 如下图所示 。
一次 ES-APM 导致的概率性大量线程阻塞问题排查文章插图
我们的业务代码是这样的:
private List getTaskRules(Task task, List taskRules) {return taskRules.parallelStream().filter(taskRule -> taskRule.getTaskId().equals(task.getId())).sorted(Comparator.comparing(TaskRule::getLower)).collect(Collectors.toList());}parallelStream 背后的男人是 ForkJoin , 采用分治的方式将任务分解为小任务 , 然后通过 ForkJoinPool 线程池来实现并行化 。
ES-APM 为了突破跨线程链路追踪 , 对多线程相关的类做了注入 , apm-java-concurrent-plugin 插件会注入所有 ForkJoinTask 的子类 , ForkJoin 底层实现用到的很多类都继承了 ForkJoinTask , 比如下面这些:

  • java.util.stream.Nodes$CollectorTask
  • java.util.stream.Nodes$ToArrayTask$OfRef
  • java.util.stream.ReduceOps$ReduceTask
  • java.util.concurrent.CountedCompleter
  • ...
在服务启动后 , 大量的 HTTP 请求进来调用 getTaskRules 这个方法 , HTTP 线程、ForkJoinPool 中的线程都会调用到 ES-APM 的代码 , 判断这些类有没有被字节码注入 。 ES-APM 判断类有没有被转换的代码如下:
一次 ES-APM 导致的概率性大量线程阻塞问题排查文章插图
上面的代码有一个明显的并发问题 , 这里的逻辑是首先查询类有没有被转换 , 如果没有 , 则进入到一个类锁 , 做相关类的字节码注入 。
在并发量高的情况下 , HTTP 线程、ForkJoinPool 中的线程调用了 getOrCreate 方法 , 这时因为类还没有转换 , 返回了一个空的 set , 然后有一个幸运儿抢到了 ElasticApmAgent 类锁 , 其它所有的线程都 block 住了 。
当幸运儿执行完类的转换 , 下一个抢到类锁的线程还会再对类转换一遍(可怕) 。 其它的没抢到的还要继续 block 。 不仅如此 , 因为 ForkJoinPool 线程池中的线程也会 block 在这个 , 导致 http 请求也会 block , 很快整个 tomcat 线程池就被耗尽了 。
这还没完 , 其实如果处理的非常快 , 也没有什么太大的问题 , 只是同一个类 , 每经过一次改写 , 就会变复杂 , 文件变得更大 , 下次类的字节码注入花的时间就更长 。
使用 arthas 去注入 Bytebuddy 的 AgentBuilder$Default$ExecutingTransformer.transform 方法 , 这个方法的签名如下 。
private byte[] transform(JavaModule module,ClassLoader classLoader,String internalTypeName,Class classBeingRedefined,ProtectionDomain protectionDomain,byte[] binaryRepresentation) {}其中 internalTypeName 表示要转换的类的类名 , binaryRepresentation 表示当前转换类最新的字节码数据 。
启动 arthas , 开启 unsafe:
options unsafe true然后使用 watch 命令观察
watch co.elastic.apm.agent.shaded.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer transform"{params}" -x 2ts=2020-10-22 03:41:52; [cost=0.358887ms] result=@ArrayList[@Object[][null,null,@String[java/util/concurrent/CountedCompleter],@Class[class java.util.concurrent.CountedCompleter],null,@byte[][isEmpty=false;size=4379],],]...ts=2020-10-22 03:47:26; [cost=1021.689119ms] result=@ArrayList[@Object[][null,@String[java/util/concurrent/CountedCompleter],@Class[class java.util.concurrent.CountedCompleter],null,@byte[][isEmpty=false;size=88422],],]ts=2020-10-22 03:50:27; [cost=1419.025166ms] result=@ArrayList[@Object[][null,@String[java/util/concurrent/CountedCompleter],@Class[class java.util.concurrent.CountedCompleter],null,@byte[][isEmpty=false;size=102910],],]