搜索

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

捉虫大师

共 15021字，需浏览 31分钟

 ·

2023-06-28 20:33

本文是一位朋友的作品，之前他向我咨询了如何给 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是空的.

主要环境说明:

  1. JDK 1.8
  2. skywalking agent 8.14.0
  3. spring boot 2.2.6.RELEASE
三、排查过程

3.1 关于 AgentClassLoader 的一个发现

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

eb5ad532dbdd097a4320023b5eafc6fc.webpb132e97cc1519ed7291407bff9efed6d.webp

我觉得扫描 plugins 目录中 jar 包这个事情应该只做一次就行了, 基于这个日志去搜索了一下源码, 发现这个动作是在 skywalking 的自定义类加载器AgentClassLoader中的findClass方法中触发的, 但是奇怪的是我看到扫描 jar 包这个事情是有缓存的, 理论上只会做一次才对, 为什么触发两次?

在扫描 jar 包的入口代码处打了断点调试, 发现确实进来了两次, 但是从 debug 的视图看到, 两次进来的AgentClassLoader是 2 个不同的实例。

bb61909bbde0b7fab2144dddca508316.webp060d60b16173a32728a4927c36588e85.webp

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 个问题:

  1. 线程池插件在 merge 到主干时一定是经过测试, 且有测试用例提交的, 为什么官方的测试用例可以通过?
  2. 如果是因为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(即字节码增强).

调用序列图:

e7ed129867bf4a8b079bb4084d261fee.webp

虽然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 种.

  1. AgentClassLoader变成单例, 避免重复扫描 jar 包导致的日志输出, 从而避免日志组件对ThreadPoolExecutor的依赖.
  2. 去除日志组件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
浏览 22
点赞
评论
收藏
分享

手机扫一扫分享

分享
举报
评论
图片
表情
推荐
线程池的一个BUG，被我发现了
Java专栏
0
线程池的一个BUG，被我发现了
码农突围
0
JDK中线程池的一个BUG，被我发现了！
业余草
0
动态线程池上线了...
源码兴趣圈
0
一年了
嵌入式Linux
0
我解决了一个重大BUG！
艾小仙
0
太极限了，JDK的这个BUG都能被我踩到
Kirito的技术分享
0
太极限了，JDK的这个BUG都能被我踩到
低并发编程
0
太极限了，JDK的这个BUG都能被我踩到
码农沉思录
0
转行一年了
关注、星标公众号，直达精彩内容ID：技术让梦想更伟大整理：李肖遥来公司一年了。    说是转行其实还是在半导体行业，熟悉我的朋友知道 ，我在18年开始进入半导体行业，那个时候想着行业很重要，站对了搞不好就飞起来了。要么互联网要么半导体，后来觉得技术栈更符合半导
点赞
评论
收藏
分享

手机扫一扫分享

分享
举报