性能文章>一次 ES-APM 导致的大量线程阻塞问题排查>

一次 ES-APM 导致的大量线程阻塞问题排查原创

7225013

前段时间我们接入了某公司出品的 Elastic-APM 作为全链路监控平台,终结了我好几年前撸的字节码注入全链路监控平台。前段时间有一个业务在启动过程中,会概率性出现大量线程阻塞,导致可对外提供服务的 HTTP 线程非常少,流量进来以后马上出现 HTTP 线程耗尽,健康检查接口请求失败,服务被 k8s 杀死。

image.png

堆栈分析

既然是线程的问题,当然想到的是 dump 线程堆栈,人肉阅读也可以,上传到 PerfMa XSheepdog 会更加简单。在锁的这一栏的截图如下所示。

image.png

可以看到 http-nio-18880-exec-44 线程持有了一个锁,这个锁被其它的 199 个线程等待。持有锁的线程堆栈如下图所示。

image.png

上层的调用方法是 co.elastic.apm.agent.bci.ElasticApmAgent#ensureInstrumented,这段逻辑背后是在调用 bytebuddy 利用 ASM 进行 class 的转换注入。

等待锁的线程恰好 block 也在这个方法,如下图所示。

image.png

通过堆栈分析,这个问题的出现与我们业务代码用了 ParallelStream 有关。Java 中的 Stream 是一个比较好用的东西,在函数式编程、流式数据处理上写起来比较简单。除了串行化的流式处理,Java 也提供了并行流 parallelStream 可以使用多核多线程并行处理,如下图所示。

image.png

我们的业务代码是这样的:

private List<TaskRule> getTaskRules(Task task, List<TaskRule> 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 判断类有没有被转换的代码如下:

image.png

上面的代码有一个明显的并发问题,这里的逻辑是首先查询类有没有被转换,如果没有,则进入到一个类锁,做相关类的字节码注入。

在并发量高的情况下,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 2

ts=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],
    ],
]

可以看到 CountedCompleter 类经过多次转换,从几 k 大小变为了 100k 以上,继续转换还变得更大,代码变得更复杂,ASM 注入字节码的时间会变得越来越长,表现出来的现象就是:

持有锁的线程花在转换类的时间会越来越长
相应的,等待锁的线程将要等待更久的时间
我在代码中加了一些打印,time 后面的两个数字,第一个是 ensureInstrumented 整个方法的耗时,第二个是 Bytebuddy 字节码注入的耗时,单位都是毫秒。

[06:15:32][http-nio-18880-exec-49]done:class java.util.stream.Nodes$CollectorTask time:313 306
[06:15:33][http-nio-18880-exec-45]done:class java.util.stream.Nodes$ToArrayTask$OfRef time:496 233
...
[06:15:50][http-nio-18880-exec-17]done:class java.util.stream.Nodes$ToArrayTask$OfRef time:18317 1075
...
[06:16:54][http-nio-18880-exec-27]done:class java.util.stream.Nodes$ToArrayTask$OfRef time:81713 5481
...
[06:22:51][http-nio-18880-exec-59]done:class java.util.stream.Nodes$CollectorTask time:438733 24975
...

可以看到等锁的线程,有的等了 400 多秒,bytebuddy 字节码注入的时间也在快速增大,后面甚至要几分钟。

验证

为了侧面印证前面的分析过程,可以验证这样的情况:第一次只有一个请求,没有用户造成的并发情况,让并发相关的类都快速注入完成,再来做压测,看看还会不会出问题。步骤如下:

  • 第一步,等服务启动完,使用 curl 请求,先请求一次接口。
  • 然后使用 ab 或者 jmeter 疯狂来压那个接口,看看接口的响应情况。
    结果如预料中的一样,接口响应时间正常了,jstack 查看现场的堆栈,也没有任何线程阻塞等在 ElasticApmAgent 的类锁上了。

解决办法

最简单的解决是业务暂时去掉 parallelStream,有坑先绕过。还有一个不成熟的改法,也不知道对不对:把 synchronized 同步块里的鸡肋二次判断 contains 前面加一行获取最新 appliedInstrumentations 的逻辑,如下所示,如果已经转换过了,就可以跳过后面的逻辑了。

image.png

经过重新打包 ES-APM 进行测试,确实解决了这个场景下的问题。

小结

出问题的时候,不要怀疑自己,大胆的怀疑框架吧,ES-APM 这个调用超级频繁的代码中有一个类锁性能好不到哪里去,有很大的改善空间。好了,落班。

分类:
标签:
请先登录,再评论

暂无回复,快来写下第一个回复吧~

为你推荐

字符串字面量长度是有限制的
前言 偶然在一次单元测试中写了一个非常长的字符串字面量。 正文 在一次单元测试中,我写了一个很长的字符串字面量,大概10万个字符左右,编译时,编译器给出了异常告警 `java: constant
多次字符串相加一定要用StringBuilder而不用-吗?
今天在写一个读取Java class File并进行分析的Demo时,偶然发现了下面这个场景(基于oracle jdk 1.8.0_144): ``` package test; public c
如何通过反射获得方法的真实参数名(以及扩展研究)
前段时间,在做一个小的工程时,遇到了需要通过反射获得方法真实参数名的场景,在这里我遇到了一些小小的问题,后来在部门老大的指导下,我解决了这个问题。通过解决这个问题,附带着我了解到了很多新的知识,我觉得
高吞吐、低延迟 Java 应用的 GC 优化实践
本篇原文作者是 LinkedIn 的 Swapnil Ghike,这篇文章讲述了 LinkedIn 的 Feed 产品的 GC 优化过程,虽然文章写作于 April 8, 2014,但其中的很多内容和
「每日五分钟,玩转 JVM」:久识你名,初居我心
聊聊 JVMJVM,一个熟悉又陌生的名词,从认识Java的第一天起,我们就会听到这个名字,在参加工作的前一两年,面试的时候还会经常被问到JDK,JRE,JVM这三者的区别。JVM可以说和我们是老朋友了
据说99.99%的人都会答错的类加载的问题
概述首先还是把问题抛给大家,这个问题也是我厂同学在做一个性能分析产品的时候碰到的一个问题。 同一个类加载器对象是否可以加载同一个类文件多次并且得到多个Class对象而都可以被java层使用吗请仔细注意
Java多线程——并发测试
编写并发程序时候,可以采取和串行程序相同的编程方式。唯一的难点在于,并发程序存在不确定性,这种不确定性会令程序出错的地方远比串行程序多,出现的方式也没有固定规则。那么如何在测试中,尽可能的暴露出这些问
Java多线程知识小抄集(一)
本文主要整理笔者遇到的Java多线程的相关知识点,适合速记,故命名为“小抄集”。本文没有特别重点,每一项针对一个多线程知识做一个概要性总结,也有一些会带一点例子,习题方便理解和记忆。 1.interr