skywalking 沉了一年的线程池插件 bug 被我解决了

夏奇2023年06月26日约 12 分钟

本文是一位朋友的作品，之前他向我咨询了如何给 skywalking 贡献代码，我说你搞完了可以写篇文章。原文发表在 infoQ：https://xie.infoq.cn/article/9ececbb4179729a8708f4c27e，点击文章底部阅读原文直达。

一、Talk is cheap, show you the code

修复了某些场景下 线程池插件增强失败 的问题，心急的人可以直接看问题及代码。

以下是我提交的 issue 和 PR(已经被 merged)：

issue: https://github.com/apache/skywalking/issues/10925
pull request: https://github.com/apache/skywalking-java/pull/556

二、背景

最近公司在做全链路追踪，在 agent 这块使用 skywalking 作为核心实现。同步链路 trace 的覆盖基本上都有 plugin 实现了，对于异步链路 trace 这块开源社区也已经有了线程池的增强 plugin（


  bootstrap-plugins\apm-jdk-threadpool-plugin.jar

）. 首先, 需要把


  bootstrap-plugins\apm-jdk-threadpool-plugin.jar

移动到


  plugins

目录下. 但是在应用启动之后的使用过程中，发现线程池增强失败了，表现出来的是在线程池中提交的任务打印日志的


  traceId

是空的. 主要环境说明:

JDK 1.8
skywalking agent 8.14.0
spring boot 2.2.6.RELEASE

三、排查过程

3.1 关于 AgentClassLoader 的一个发现

这个发现纯粹是一个巧合, 我发现在控制台和 skywalking-api.log 中都有同样的一份扫描 plugins 目录中 jar 包的相关日志

我觉得扫描 plugins 目录中 jar 包这个事情应该只做一次就行了, 基于这个日志去搜索了一下源码, 发现这个动作是在 skywalking 的自定义类加载器


  AgentClassLoader

中的


  findClass

方法中触发的, 但是奇怪的是我看到扫描 jar 包这个事情是有缓存的, 理论上只会做一次才对, 为什么触发两次? 在扫描 jar 包的入口代码处打了断点调试, 发现确实进来了两次, 但是从 debug 的视图看到, 两次进来的


  AgentClassLoader

是 2 个不同的实例。


  AgentClassLoader

被实例化了 2 次?! 因为本身类的字节码增强就是在类加载的阶段去做的, 而增强字节码主要是靠 plugins 中的 Interceptor, 然后 plugins 中的 class 都是由


  AgentClassLoader

进行加载的, 所以我这里本能的怀疑跟


  AgentClassLoader

被实例化了 2 次有关系. 带着这样的怀疑, 我排查了


  AgentClassLoader

被实例化的地方. 在


  AgentClassLoader

的构造器中打了断点, 发现第一次是在 premain 方法 agent 刚启动的时候去实例化了, 第二次是 premain 方法已经执行完毕, 在 main 方法启动时第一次加载 plugins 中的 Interceptor 类时去实例化了. 第二次实例化的代码在


  InterceptorInstanceLoader

类中的


  load

方法

public class InterceptorInstanceLoader {

    public static <T> T load(String className,
        ClassLoader targetClassLoader) throws IllegalAccessException, InstantiationException, ClassNotFoundException, AgentPackageNotFoundException {
        if (targetClassLoader == null) {
            targetClassLoader = InterceptorInstanceLoader.class.getClassLoader();
        }
        String instanceKey = className + "_OF_" + targetClassLoader.getClass()
                                                                   .getName() + "@" + Integer.toHexString(targetClassLoader
            .hashCode());
        Object inst = INSTANCE_CACHE.get(instanceKey);
        if (inst == null) {
            INSTANCE_LOAD_LOCK.lock();
            ClassLoader pluginLoader;
            try {
                pluginLoader = EXTEND_PLUGIN_CLASSLOADERS.get(targetClassLoader);
                // ------------------- 关键代码在这里 -------------------
                if (pluginLoader == null) {
                    pluginLoader = new AgentClassLoader(targetClassLoader);
                    EXTEND_PLUGIN_CLASSLOADERS.put(targetClassLoader, pluginLoader);
                }
            } finally {
                INSTANCE_LOAD_LOCK.unlock();
            }
            inst = Class.forName(className, true, pluginLoader).newInstance();
            if (inst != null) {
                INSTANCE_CACHE.put(instanceKey, inst);
            }
        }

        return (T) inst;
    }
}

因为已经认定了


  AgentClassLoader

就应该是单例的, 这里是重复实例化了, 所以我把这里的源码改成了复用第一次实例化的


  AgentClassLoader

对象.

重新打包 agent -> 启动应用 -> 观察

首先, 扫描 jar 包的日志只剩一份了(在控制台), 接下来测试线程池的调用, 发现这个时候线程池的增强起作用了, 表现为日志中能看到 traceId 的值, 且和主线程中日志的 traceId 一致.

测试代码:

    @GetMapping(value = "testHello")
    public String testHello(@RequestParam("msg") String msg){
        log.info("testHello:{}, traceId:{}", msg, org.apache.skywalking.apm.toolkit.trace.TraceContext.traceId());
        ThreadPoolExecutor executor = new ThreadPoolExecutor(10, 10, 1000, TimeUnit.HOURS, new ArrayBlockingQueue<>(10));
        executor.submit(() -> {
            log.info("executor.execute:{}, traceId:{}", msg, org.apache.skywalking.apm.toolkit.trace.TraceContext.traceId());
        });
       return "ok";
    }

日志输出:

2023-06-21 20:38:55.359  INFO 20808 - [nio-8081-exec-1] c.ScController   : testHello:111, traceId:753241bce942437a9cfd0daea7e21578.65.16873511352010001
2023-06-21 20:38:55.368  INFO 20808 - [pool-2-thread-2] c.ScController   : executor.execute:111, traceId:753241bce942437a9cfd0daea7e21578.65.16873511352010001

在对


  AgentClassLoader

使用单例后问题解决. 但是问题就此结束了吗? 看了下 git commit 历史记录,


  AgentClassLoader

的实例化代码一直都没有变过, 如果是因为


  AgentClassLoader

的重复实例化问题导致的, 那么有 2 个问题:

线程池插件在 merge 到主干时一定是经过测试, 且有测试用例提交的, 为什么官方的测试用例可以通过?
如果是因为 AgentClassLoader 的重复实例化问题导致的, 那么理论上其他类的增强也会出问题, 但是其他类的增强为什么没问题呢?

基于上面两个问题, 我觉得"因为


  AgentClassLoader

的重复实例化"这个原因似乎并不是根因。 也就是说线程池插件一定能生效, but how or when?

3.2 ThreadPoolExecutor 的类加载时机

尝试用最简 plugins 配置(因为官方的 test case 都是单个插件单独测试的, 怀疑是不是插件之间的有一些冲突或者不兼容的问题), 只保留了


  tomcat-7.x-8.x-plugin-8.14.0.jar

和


  apm-jdk-threadpool-plugin-8.14.0.jar

果然，启动应用之后再调用线程池的方法，发现 traceId 就正常生效了，也就是插件增强成功。

我想到的是, 字节码增强是在类加载的时候触发了 transform 操作( 注: 类加载完之后也能 retransform, 但是这个不在本文的讨论范围内 ), 会不会是在 skywalking 注册 transformer 之前


  ThreadPoolExecutor

已经被加载到 JVM 中了呢? 带着这个疑问, 我在应用启动时增加了


  -XX:+TraceClassLoading

参数, 打印了类加载的具体情况, 如下:

[Opened C:\Users\xiaqi\.jdks\corretto-1.8.0_372\jre\lib\rt.jar]
[Loaded java.lang.Object from C:\Users\xiaqi\.jdks\corretto-1.8.0_372\jre\lib\rt.jar]
...
[Loaded java.lang.Runnable from C:\Users\xiaqi\.jdks\corretto-1.8.0_372\jre\lib\rt.jar]
[Loaded java.lang.Thread from C:\Users\xiaqi\.jdks\corretto-1.8.0_372\jre\lib\rt.jar]
...
---------------------------------------------------agent jar包加载---------------------------------------------------
[Loaded org.apache.skywalking.apm.agent.SkyWalkingAgent from file:/D:/IdeaProjects/skywalking-agent/skywalking-agent/skywalking-agent.jar]
...
---------------------------------------------------准备注册transformer---------------------------------------------------------
[Loaded org.apache.skywalking.apm.dependencies.net.bytebuddy.agent.builder.AgentBuilder$Transformer from file:/C:/Users/xiaqi/IdeaProjects/skywalking-agent/skywalking-agent/skywalking-agent.jar]
[Loaded org.apache.skywalking.apm.dependencies.net.bytebuddy.agent.builder.AgentBuilder$RedefinitionStrategy$Listener from file:/C:/Users/xiaqi/IdeaProjects/skywalking-agent/skywalking-agent/skywalking-agent.jar]
[Loaded org.apache.skywalking.apm.dependencies.net.bytebuddy.agent.builder.AgentBuilder$Listener from file:/C:/Users/xiaqi/IdeaProjects/skywalking-agent/skywalking-agent/skywalking-agent.jar]
...
[Loaded org.apache.skywalking.apm.dependencies.net.bytebuddy.implementation.bind.MethodDelegationBinder$1 from file:/D:/IdeaProjects/skywalking-agent/skywalking-agent/skywalking-agent.jar]
[Loaded org.apache.skywalking.apm.dependencies.net.bytebuddy.implementation.bind.MethodDelegationBinder$AmbiguityResolver$Resolution from file:/D:/IdeaProjects/skywalking-agent/skywalking-agent/skywalking-agent.jar]
---------------------------------------------------注册transformer结束---------------------------------------------------------
...
[Loaded java.util.concurrent.ThreadPoolExecutor from C:\Users\xiaqi\.jdks\corretto-1.8.0_372\jre\lib\rt.jar]
...

从上面的日志中可以看出来,


  ThreadPoolExecutor

是在注册了 transformer 之后, 因此不符合我上面的猜测. 这里顺便说一下, 从上面的日志中看得出来,


  Runnable

和


  Thread

这 2 个类都是在 JVM 刚启动时且 agent 尚未加载时就已经被加载到 JVM 中了, 因此这 2 个类想要做字节码增强是非常困难的. 既然从类加载的顺序上看不出来问题, 我决定看一下第一次使用


  ThreadPoolExecutor

是在具体干什么. 于是我在


  ThreadPoolExecutor

的构造器上打了断点, 正常启动应用后进入了断点, 调用栈如下:

<init>:1310, ThreadPoolExecutor (java.util.concurrent)
<init>:1237, ThreadPoolExecutor (java.util.concurrent)
<init>:447, ScheduledThreadPoolExecutor (java.util.concurrent)
newSingleThreadScheduledExecutor:272, Executors (java.util.concurrent)
<init>:66, FileWriter (org.apache.skywalking.apm.agent.core.logging.core)
get:56, FileWriter (org.apache.skywalking.apm.agent.core.logging.core)
getLogWriter:49, WriterFactory (org.apache.skywalking.apm.agent.core.logging.core)
logger:207, AbstractLogger (org.apache.skywalking.apm.agent.core.logging.core)
info:72, AbstractLogger (org.apache.skywalking.apm.agent.core.logging.core)
doGetJars:197, AgentClassLoader (org.apache.skywalking.apm.agent.core.plugin.loader)
getAllJars:177, AgentClassLoader (org.apache.skywalking.apm.agent.core.plugin.loader)
findClass:94, AgentClassLoader (org.apache.skywalking.apm.agent.core.plugin.loader)
loadClass:418, ClassLoader (java.lang)
loadClass:351, ClassLoader (java.lang)
forName0:-1, Class (java.lang)
forName:348, Class (java.lang)
load:71, InterceptorInstanceLoader (org.apache.skywalking.apm.agent.core.plugin.loader)
<init>:48, ConstructorInter (org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance)
enhanceInstance:124, ClassEnhancePluginDefine (org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance)
enhance:116, AbstractClassEnhancePluginDefine (org.apache.skywalking.apm.agent.core.plugin)
define:96, AbstractClassEnhancePluginDefine (org.apache.skywalking.apm.agent.core.plugin)
transform:167, SkyWalkingAgent$Transformer (org.apache.skywalking.apm.agent)
doTransform:12104, AgentBuilder$Default$ExecutingTransformer (org.apache.skywalking.apm.dependencies.net.bytebuddy.agent.builder)
transform:12041, AgentBuilder$Default$ExecutingTransformer (org.apache.skywalking.apm.dependencies.net.bytebuddy.agent.builder)
access$1800:11758, AgentBuilder$Default$ExecutingTransformer (org.apache.skywalking.apm.dependencies.net.bytebuddy.agent.builder)
run:12441, AgentBuilder$Default$ExecutingTransformer$LegacyVmDispatcher (org.apache.skywalking.apm.dependencies.net.bytebuddy.agent.builder)
run:12381, AgentBuilder$Default$ExecutingTransformer$LegacyVmDispatcher (org.apache.skywalking.apm.dependencies.net.bytebuddy.agent.builder)
doPrivileged:-1, AccessController (java.security)
doPrivileged:11936, AgentBuilder$Default$ExecutingTransformer (org.apache.skywalking.apm.dependencies.net.bytebuddy.agent.builder)
transform:11950, AgentBuilder$Default$ExecutingTransformer (org.apache.skywalking.apm.dependencies.net.bytebuddy.agent.builder)
transform:188, TransformerManager (sun.instrument)
transform:428, InstrumentationImpl (sun.instrument)
defineClass1:-1, ClassLoader (java.lang)
defineClass:756, ClassLoader (java.lang)
defineClass:142, SecureClassLoader (java.security)
defineClass:473, URLClassLoader (java.net)
access$100:74, URLClassLoader (java.net)
run:369, URLClassLoader$1 (java.net)
run:363, URLClassLoader$1 (java.net)
doPrivileged:-1, AccessController (java.security)
findClass:362, URLClassLoader (java.net)
loadClass:418, ClassLoader (java.lang)
loadClass:352, Launcher$AppClassLoader (sun.misc)
loadClass:351, ClassLoader (java.lang)
registerAnnotationConfigProcessors:170, AnnotationConfigUtils (org.springframework.context.annotation)
registerAnnotationConfigProcessors:137, AnnotationConfigUtils (org.springframework.context.annotation)
<init>:88, AnnotatedBeanDefinitionReader (org.springframework.context.annotation)
<init>:71, AnnotatedBeanDefinitionReader (org.springframework.context.annotation)
<init>:73, AnnotationConfigServletWebServerApplicationContext (org.springframework.boot.web.servlet.context)
newInstance0:-1, NativeConstructorAccessorImpl (sun.reflect)
newInstance:62, NativeConstructorAccessorImpl (sun.reflect)
newInstance:45, DelegatingConstructorAccessorImpl (sun.reflect)
newInstance:423, Constructor (java.lang.reflect)
instantiateClass:204, BeanUtils (org.springframework.beans)
instantiateClass:139, BeanUtils (org.springframework.beans)
createApplicationContext:588, SpringApplication (org.springframework.boot)
run:311, SpringApplication (org.springframework.boot)
run:1226, SpringApplication (org.springframework.boot)
run:1215, SpringApplication (org.springframework.boot)
main:18, DemoClientApplication (com.demo.client)

通过调用栈, 我发现


  ThreadPoolExecutor

的第一次实例化是在 skywalking 的日志组件


  FileWriter

的实例化中触发的. 但是这个调用栈比较诡异的点就在于触发这个的上层调用是因为引入了 spring 的 plugin 而导致加载 spring 中的


  AutowiredAnnotationBeanPostProcessor

类的时候触发了 transform(字节码增强), 并且在 transform 阶段依赖了


  ThreadPoolExecutor

, 而在对


  AutowiredAnnotationBeanPostProcessor

类的 transform 还没有结束时, 似乎在这个时候被依赖的


  ThreadPoolExecutor

类并不会再次触发 transform(即字节码增强). 调用序列图:

虽然


  ThreadPoolExecutor类

在这里没有触发 transform, 但是类已经确确实实被加载到 JVM 了, 而类只会被加载一次, 也就是说后面不会再进行


  ThreadPoolExecutor

的类加载, 也就不会进行字节码增强了.

3.3 关于 JVM 对于 transform 逻辑的猜想

JVM 对于已经在类 A 的 transform 阶段依赖的类 B 的类加载行为不会再触发类 B 的 transform.

猜测这个逻辑是 JVM 为了防止循环调用 transform 而导致栈溢出的问题.

假如类 B 也会触发 transform, 那么可能会出问题的循环逻辑如下:

类 A 加载 -> 类 A transform

-> transformer 中的类 B 加载 -> 类 B transform(这次类 B 还未完成类加载过程)

-> transformer 中的类 B 加载 -> 类 B transform(这次类 B 还未完成类加载过程)

...

为了进一步验证这个猜想, 我把 skywalking 中的


  FileWriter

中创建线程池的代码注释掉了, 然后再次启动应用, 发现线程池插件增强成功, 这个结果和我的猜想是相符的.

但是这里又有一个疑问:

如果是因为 transform 的逻辑问题, 那么只要存在需要被增强的类, 则一定会有这个问题, 但是为什么上面我验证了只有 tomcat 插件和线程池插件的时候, 线程池插件是可以正常生效的呢?

后来, 我发现对于 JDK 中的类的增强和三方类库中类的增强的逻辑是不一样的. JDK 中的类的增强在 transform 阶段是不会去调用


  AgentClassLoader

去加载 Interceptor 类, 而是在刚开始的时候就用模板动态定义好了 Interceptor 类, 并由


  AppClassLoader

完成了加载. 而


  AppClassLoader

是不依赖


  ThreadPoolExecutor

的. 也就是说, 在


  ThreadPoolExecutor

增强之前如果有三方类库的类先被增强了, 最后


  ThreadPoolExecutor

就会增强失败, 否则就不会有问题了.(划重点) 关于 JDK 中的类的增强的逻辑可以具体看


  BootstrapInstrumentBoost

这个类的实现逻辑.

注: 由于没有去看 JVM 的源码, 这个地方的猜想是不严谨的. 后面有时间我会再去研究一下 JVM 在这块的源码. 如果有经验的同学也可以在后面留言给我说明实际源码的逻辑是怎么样的, 不胜感激.

3.4 问题总结

至此, 所有的疑问都解开了.

上面在 3.1 章节的最后提出的 2 个问题, 就可以回答了.

Q: 线程池插件在 merge 到主干时一定是经过测试, 且有测试用例提交的, 为什么官方的测试用例可以通过? A: 官方的测试用例是单个 plugin 去测试的, 此时只有


  ThreadPoolExecutor

被增强, 不存在三方类库增强的问题, 因此可以正常生效. Q: 如果是因为


  AgentClassLoader

的重复实例化问题导致的, 那么理论上其他类的增强也会出问题, 但是其他类的增强为什么没问题呢? A:


  ThreadPoolExecutor

增强失败的问题主要是因为对三方类库增强的 transform 阶段依赖了


  ThreadPoolExecutor

, 而其他类的增强没有这样的情况. 至于把


  AgentClassLoader

改成单例之后为什么就没问题了, 是因为这样就不会重复扫描 plugins 目录中 jar 包, 也就不会打日志, 也就是 transform 阶段就不依赖


  ThreadPoolExecutor

了, 因此不会有问题.

四、解决方案

排查原因很曲折, 解决方案很简单, 我能想到的有 2 种.

AgentClassLoader 变成单例, 避免重复扫描 jar 包导致的日志输出, 从而避免日志组件对 ThreadPoolExecutor 的依赖.
去除日志组件 FileWriter 对于 ThreadPoolExecutor 的依赖, 改为其他的实现.

第一种方案, 在和 @吴晟 大佬讨论之后被否决了, 原因是大佬说


  AgentClassLoader

的多例是一种简单的代理模式, 在还没有深入理解这里的设计思想的前提下, 还是选择了尊重权威. 最后用了第二种方案作为实现思路.


  FileWriter

中


  ThreadPoolExecutor

是为了定时把日志刷到文件中. 首先, 我想到的是用


  Timer

和


  TimerTask

来做替代方案, 但是实际上谁也不知道后面会不会有增强


  Timer

和


  TimerTask

的插件出现, 因此最后采用了简单的 Thread+循环的方式做了替代方案. 具体的实现代码可以看我最开始贴的 PR 链接.

五、相关的 issues 和 discussions

从源码提交记录来看, 线程池的 plugin 是从 2022 年 4 月第一次提交的, 这一年我也看到有人陆续反馈了线程池增强失败的问题, 但是一直没有得到解决。现在已经被我解决啦，在未来的 skywalking agent 8.17.0 版本就能用上了。

以下是相关的 issues 和 discussions：

https://github.com/apache/skywalking/issues/9425
https://github.com/apache/skywalking/issues/9850
https://github.com/apache/skywalking/issues/10374
https://github.com/apache/skywalking/issues/10685
https://github.com/apache/skywalking/discussions/10207
https://github.com/apache/skywalking/discussions/9888

一、Talk is cheap, show you the code

二、背景

三、排查过程

3.1 关于 AgentClassLoader 的一个发现

3.2 ThreadPoolExecutor 的类加载时机

3.3 关于 JVM 对于 transform 逻辑的猜想

3.4 问题总结

四、解决方案

五、相关的 issues 和 discussions

来自同一个声音

务必立即拿下软考证（政策红利）

[翻译]从 unique 到 cleanups 和 weak：高效的新底层工具

Go 什么时候该使用协程池？

快速学习 Go 1.24 的 Swiss Tables