[Bug] apm-jdk-threadpool-plugin does not work in certain scenarios

[xiaqi1210]

Search before asking

• I had searched in the issues and found no similar issues.

Apache SkyWalking Component

Java Agent (apache/skywalking-java)

What happened

I moved the apm-jdk-threadpool-plugin.jar to the plugins directory and started a Spring Boot application. In a controller method, I added an invocation of ThreadPoolExecutor and printed the traceId. However, I noticed that the traceId is showing as "N/A," which means that the ThreadPoolExecutor class has not been enhanced.

What you expected to happen

The ThreadPoolExecutor class should be enhanced and able to print a valid traceId.

How to reproduce

1. jdk 1.8
2. skywalking agent 8.14.0
3. spring boot application (spring boot 2.2.6.RELEASE), add apm-toolkit-trace to pom.xml
4. In the plugins directory of the Skywalking agent, keep the following JAR files: apm-jdk-threadpool-plugin-8.14.0.jar, apm-spring-core-patch-8.14.0.jar, and tomcat-7.x-8.x-plugin-8.14.0.jar. In the activations directory, keep the apm-toolkit-trace-activation-8.14.0.jar.
5. The controller code for the Spring Boot application is as follows.

    @GetMapping(value = "testHello")
    public String testHello(){
        ThreadPoolExecutor ThreadPoolExecutor = new ThreadPoolExecutor(1,1,1000, TimeUnit.SECONDS, new ArrayBlockingQueue<>(10));
        ThreadPoolExecutor.execute(()->{
            log.info("traceId:"+TraceContext.traceId());
        });
        return "ok";
    }

6. start the application with skywalking agent
7. call the controller method, then see the traceId in log

Anything else

In the reproduction steps mentioned above, if I only keep apm-jdk-threadpool-plugin-8.14.0.jar and tomcat-7.x-8.x-plugin-8.14.0.jar in the plugins directory, excluding apm-spring-core-patch-8.14.0.jar, then the thread pool plugin will work correctly.

This is because when the Skywalking agent performs class transformation on the classes in the application, it first uses the AgentClassLoader to load the corresponding interceptor classes. When the AgentClassLoader loads a class for the first time, it scans the plugins directory and outputs logs. The logs are written using FileWriter, which depends on ThreadPoolExecutor during instantiation. At this point, since the transformation process for the class that needs to be enhanced has not yet completed, I found that the class loading of ThreadPoolExecutor will not trigger the transformation process again (I speculate that this is to avoid circular dependencies during the transform phase in JVM).

In other words, if there are many classes in the plugins that need to be enhanced, but the class loading of ThreadPoolExecutor during application startup is later than the class loading of other classes that need enhancement (i.e., ThreadPoolExecutor is not the first class to be enhanced), it will result in the failure to enhance ThreadPoolExecutor. Excluding apm-spring-core-patch-8.14.0.jar, as mentioned earlier, is to ensure that ThreadPoolExecutor is the first class to be enhanced during application startup.

I have two solutions:

1. Solution A: Avoid scanning the plugins directory when loading interceptor classes. In fact, during the execution of the agent's premain method, the AgentClassLoader has already scanned the directory once, and the result of this scan can be reused.

2. Solution B: Modify the implementation of FileWriter to use an alternative approach instead of relying on ThreadPoolExecutor. In this case, you can use a combination of Timer and TimerTask to schedule periodic log flushing to a file. Additionally, it would be beneficial to make this implementation configurable.

Are you willing to submit PR?

• Yes I am willing to submit a PR!

Code of Conduct

• I agree to follow this project's Code of Conduct

[wu-sheng]

I think your conclusion is not very accurate. As far as I can see, from your description, FileWriter is the key, which is a part of logger, rather than Class Loader.

[wu-sheng]

And if you want to fix this, you could change it by following Solution B. Again, this is not a bug about AgentClassLoader or jar file scanning, instead, this is typically instrumented target had been loaded and used in the kernel before the instrumentation.

About your Solution B, we don't have to use a combination of Timer and TimerTask to schedule periodic log. We don't know whether there is a plugin to instrument those one day like we didn't know ThreadPoolExecutor would be instrumented 5 years after the kernel was written.

Please consider using a simple native Thread and a Loop to make this work.

[xiaqi1210]

And if you want to fix this, you could change it by following Solution B. Again, this is not a bug about AgentClassLoader or jar file scanning, instead, this is typically instrumented target had been loaded and used in the kernel before the instrumentation.

About your Solution B, we don't have to use a combination of Timer and TimerTask to schedule periodic log. We don't know whether there is a plugin to instrument those one day like we didn't know ThreadPoolExecutor would be instrumented 5 years after the kernel was written.

Please consider using a simple native Thread and a Loop to make this work.

Yes, I agree with your point. The key is how to remove the dependency on ThreadPoolExecutor in the logger component. I appreciate your recognition, and I will consider your implementation suggestions. I plan to submit a pull request in the next few days to address this issue.

[wu-sheng]

Fixed by apache/skywalking-java#556