TTL agent 与 其他agent的兼容性问题

[liauraljl]

最近发现TTL agent与其他agent共用时，TTL agent必须放在最前面；
否则会导致jdk线程池修饰失败，TTL失去作用。

比如与Skywalking Agent、Promethues等共用（未修改agent jar文件名）。

请问作者有遇到类似问题吗？

[oldratlee]

确实有其它的同学也反映过这样的问题。 👍 @liauraljl

---

你方便给一下极简的Demo @liauraljl 🙏 ♥️ ：

• 在Github建一个Demo Repo
• 包含上SkywalkingAgent、Promethues等的Agent 共用

以运行复现问题，方便我跟进排查，谢谢 😄

---

目前我觉得，可能是TTL Java Agent的设置问题，需要与不同Agent共用&生效：

transmittable-thread-local/pom.xml

Lines 268 to 272 in b1aa750

	<Premain-Class>com.alibaba.ttl.threadpool.agent.TtlAgent</Premain-Class>
	<Boot-Class-Path>${project.artifactId}-${project.version}.jar</Boot-Class-Path>
	<Can-Redefine-Classes>false</Can-Redefine-Classes>
	<Can-Retransform-Classes>true</Can-Retransform-Classes>
	<Can-Set-Native-Method-Prefix>false</Can-Set-Native-Method-Prefix>

@liauraljl 欢迎一起排查解决 😄 ♥️

PS: Java Agent的资料

[liauraljl]

• demo：https://github.com/liauraljl/ttl-agent-demo
• agent路径：https://github.com/liauraljl/ttl-agent-demo/tree/main/src/main/agentDic
• 执行结果说明：启动命令分析说明
• 启动log：https://github.com/liauraljl/ttl-agent-demo/tree/main/src/main/agentDic

[liauraljl]

基本定位到问题了，TTL agent失效是：

• 由于在TTL agent之前使用其他agent，导致ThreadPoolExecutor等类在TtlAgent premain执行之前被加载
  • 
    https://github.com/liauraljl/ttl-agent-demo/blob/main/src/main/agentDic/ThreadPoolExecutor%20%E5%8A%A0%E8%BD%BD.png
  • 
    https://github.com/liauraljl/ttl-agent-demo/blob/main/src/main/agentDic/TtlAgent%E5%8A%A0%E8%BD%BD.png
• 最终线程池未被增强：
  
  https://github.com/liauraljl/ttl-agent-demo/blob/main/src/main/agentDic/ttl%20%E5%A2%9E%E5%BC%BA.png

[liauraljl]

我们目前的解决方案是

把TTL agent放在最前位置，可以保证TTL agent 正常工作。
已在开发、测试环境得到验证。

不过还是希望有更好的解决方案，
毕竟人为控制 Agent加载顺序 的话后续长期迭代难免会出错。

[TuitaKing]

我觉得这个问题可能有两方面的原因：

• SkywalkingAgent 中有ILog 这个类，他的初始化是在TTl agent之前；
  如果使用了线程池来打印日志，可能会出现还没有执行TTL中的premain的时候Runnable就已经被加载进去了。
  导致不成功。
• SkywalkingAgent中org.apache.skywalking.apm.agent.core.jvm 这个包下面包含了很多线程池，
  这些线程池是initialDelay=0的，他的初始化也是优先于TtlAgent的。

于是我尝试

1. 将SkywalkingAgent 中的日志全部切换为 System.out.println()
2. 并且去掉org.apache.skywalking.apm.agent.core.boot.BootService 文件里的类。

做完这两步后，

• 通过arthas查看加载到jvm的类的时候能够看到TtlRunnable被顺利加载进去了(开始是看不到TtlRunnable这个类的)；
• 而且输出的日志也能证明确实替换成功。 @liauraljl
• （Java启动参数 与 运行输出日志 附在 文后）

PS: 我尝试的更多运行时查看的加载类信息：

• 在TtlAgent的premain方法下面输出所有的已经加载的类（ Class[] classes = inst.getAllLoadedClasses();）
• 如果将TtlAgent放在前面，classes中是不包含线程池或者skywalking的类的
• 如果将TtlAgent放在后面，则会输出线程池和一些skywalking的类。

我觉得算是可以佐证我上面的说法。

---

Java启动参数：

java -javaagent:.../ttl-agent-demo-main/src/main/agentDic/skywalking/skywalking-agent.jar  \
    -javaagent:.../ttl-agent-demo-main/src/main/agentDic/ttl/transmittable-thread-local-2.11.5.jar=ttl.agent.logger:STDOUT \
    -jar  ttl-agent-demo-1.0.0-SNAPSHOT.jar

运行输出日志：

2021-01-11 16:52:03.855 INFO [main] TtlAgent: [TtlAgent.premain] begin, agentArgs: ttl.agent.logger:STDOUT, Instrumentation: sun.instrument.InstrumentationImpl@47af7f3d
2021-01-11 16:52:03.873 INFO [main] TtlTransformer: [TtlTransformer] add Transformlet class com.alibaba.ttl.threadpool.agent.internal.transformlet.impl.TtlExecutorTransformlet success
2021-01-11 16:52:03.874 INFO [main] TtlTransformer: [TtlTransformer] add Transformlet class com.alibaba.ttl.threadpool.agent.internal.transformlet.impl.TtlForkJoinTransformlet success
2021-01-11 16:52:03.874 INFO [main] TtlTransformer: [TtlTransformer] add Transformlet class com.alibaba.ttl.threadpool.agent.internal.transformlet.impl.TtlTimerTaskTransformlet success
2021-01-11 16:52:03.875 INFO [main] TtlAgent: [TtlAgent.premain] addTransformer class com.alibaba.ttl.threadpool.agent.TtlTransformer success
2021-01-11 16:52:03.875 INFO [main] TtlAgent: [TtlAgent.premain] end
  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.1.3.RELEASE)
2021-01-11 16:52:05.231  INFO 27164 --- [           main] c.l.d.t.TtlAgentDemoApplication          : Starting TtlAgentDemoApplication v1.0.0-SNAPSHOT on tuitaking.local with PID 27164 (/Users/tuitaking/source/ttl-agent-demo-main/target/ttl-agent-demo-1.0.0-SNAPSHOT.jar started by tuitaking in /Users/tuitaking/source/ttl-agent-demo-main/target)
2021-01-11 16:52:05.235  INFO 27164 --- [           main] c.l.d.t.TtlAgentDemoApplication          : No active profile set, falling back to default profiles: default
2021-01-11 16:52:06.750  INFO 27164 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2021-01-11 16:52:06.752 INFO [main] TtlExecutorTransformlet: insert code before method public ScheduledFuture schedule(Runnable, long, TimeUnit) of class java.util.concurrent.ScheduledThreadPoolExecutor: $1 = com.alibaba.ttl.TtlRunnable.get($1, false, true);
com.alibaba.ttl.threadpool.agent.internal.transformlet.impl.Utils.setAutoWrapperAttachment($1);
2021-01-11 16:52:06.769 INFO [main] TtlExecutorTransformlet: insert code before method public ScheduledFuture schedule(Callable, long, TimeUnit) of class java.util.concurrent.ScheduledThreadPoolExecutor: $1 = com.alibaba.ttl.TtlCallable.get($1, false, true);
com.alibaba.ttl.threadpool.agent.internal.transformlet.impl.Utils.setAutoWrapperAttachment($1);
2021-01-11 16:52:06.771 INFO [main] TtlExecutorTransformlet: insert code before method public ScheduledFuture scheduleAtFixedRate(Runnable, long, long, TimeUnit) of class java.util.concurrent.ScheduledThreadPoolExecutor: $1 = com.alibaba.ttl.TtlRunnable.get($1, false, true);
com.alibaba.ttl.threadpool.agent.internal.transformlet.impl.Utils.setAutoWrapperAttachment($1);
2021-01-11 16:52:06.773 INFO [main] TtlExecutorTransformlet: insert code before method public ScheduledFuture scheduleWithFixedDelay(Runnable, long, long, TimeUnit) of class java.util.concurrent.ScheduledThreadPoolExecutor: $1 = com.alibaba.ttl.TtlRunnable.get($1, false, true);
......

[oldratlee]

按 @liauraljl 提供的 『demo：https://github.com/liauraljl/ttl-agent-demo 』
走了一遍，确实如你的说的：👍

把TTL agent放在最前位置（如位于Skywalking Agent之前），TTL Agent的生效的。
否则Skywalking Agent在TTL agent之前，线程池未被增强，导致TTL Agent没有生效。

感谢 @liauraljl 的完整Demo、复现问题与排查～～ ♥️

---

原因 如 上面 @TuitaKing 的说明，很完整 👍 ：

因为Skywalking Agent的入口逻辑（premain）包含 线程池 的启动，导致

• 到了TTL Agent（的premain）时，TTL需要加强的线程池类已经加载（load）了。
• 而TTL Agent的TtlTransformer是在类加载时触发类的增强；如果类已经加载了会跳过TTL Agent的增强逻辑。

感谢 @TuitaKing 的详细的分析与排查～～ ♥️

---

Quote from @liauraljl

我们目前的解决方案是

把TTL agent放在最前位置，可以保证TTL agent 正常工作。
已在开发、测试环境得到验证。

COOL！

[oldratlee]

Quote from @liauraljl

不过还是希望有更好的解决方案，
毕竟人为控制 Agent加载顺序 的话后续长期迭代难免会出错。

我试着解决 Agent加载顺序 的影响：

• 实验的修改：在分支expt/fix-agent-order-problem
• 修改逻辑是：加载TtlAgent时，retransform已加载的类：4886b7e#diff-7baf52d90b056f08a33f25f27d6df84ecd50797196db42bc39b984f57ccceb2eR147-R156

使用这个TTL分支的TTL Jar，运行 @liauraljl 的 ttl-agent-demo：

• 会出java.lang.UnsupportedOperationException: class redefinition failed: attempted to change superclass or interfaces
• 即不允许retransform已经加载的类ScheduledThreadPoolExecutor
• （Java启动参数 与 运行输出日志 附在 文后）

除了，上面执行retransform碰到的异常，通过运行还可以看到：

1. 需要retransform大量已经加载的类，这个过程会比较费时；即会带来性能的影响。
2. 『retransform已加载的类』的引入，让Agent的操作流程及其实现会复杂不少；这些复杂性会有线上实现稳定性的影响。

目前个人的判断

尤其是考虑到线上实现的稳定性，目前个人的判断是

• 推荐上面 @liauraljl 可以用的解决方案，即

  我们目前的解决方案是

  把TTL agent放在最前位置，可以保证TTL agent 正常工作。
  已在开发、测试环境得到验证。

• 而不是 『retransform已加载的类』的实现方式

欢迎 @liauraljl 、 @TuitaKing 还有大家，进行更多实现或方案选择的讨论～ ♥️

---

附

Java启动参数：

java -javaagent:src/main/agentdic/skywalking/skywalking-agent.jar \
     -javaagent:path/to/transmittable-thread-local-2.13.0-SNAPSHOT.jar=ttl.agent.logger:stdout \
     -jar target/ttl-agent-demo-1.0.0-SNAPSHOT.jar

运行输出日志：

......
2021-01-18 00:26:13.408 INFO [main] TtlAgent: retransform class: class java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue
2021-01-18 00:26:13.422 INFO [main] TtlAgent: retransform class: class java.util.concurrent.ThreadPoolExecutor$AbortPolicy
2021-01-18 00:26:13.434 INFO [main] TtlAgent: retransform class: class java.util.concurrent.ScheduledThreadPoolExecutor
2021-01-18 00:26:13.438 INFO [main] TtlExecutorTransformlet: insert code before method public ScheduledFuture scheduleAtFixedRate(Runnable, long, long, TimeUnit) of class java.util.concurrent.ScheduledThreadPoolExecutor:
    $1 = com.alibaba.ttl.TtlRunnable.get($1, false, true);
    com.alibaba.ttl.threadpool.agent.internal.transformlet.impl.Utils.setAutoWrapperAttachment($1);
......
2021-01-18 00:26:13.460 INFO [main] TtlExecutorTransformlet: insert code before method public void execute(Runnable) of class java.util.concurrent.ScheduledThreadPoolExecutor:
    $1 = com.alibaba.ttl.TtlRunnable.get($1, false, true);
    com.alibaba.ttl.threadpool.agent.internal.transformlet.impl.Utils.setAutoWrapperAttachment($1);
2021-01-18 00:26:13.462 SEVERE [main] TtlAgent: Fail to load TtlAgent , cause: java.lang.UnsupportedOperationException: class redefinition failed: attempted to change superclass or interfaces
java.lang.UnsupportedOperationException: class redefinition failed: attempted to change superclass or interfaces
        at java.instrument/sun.instrument.InstrumentationImpl.retransformClasses0(Native Method)
        at java.instrument/sun.instrument.InstrumentationImpl.retransformClasses(InstrumentationImpl.java:167)
        at com.alibaba.ttl.threadpool.agent.TtlAgent.premain(Unknown Source)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at java.instrument/sun.instrument.InstrumentationImpl.loadClassAndStartAgent(InstrumentationImpl.java:513)
        at java.instrument/sun.instrument.InstrumentationImpl.loadClassAndCallPremain(InstrumentationImpl.java:525)
Exception in thread "main" java.lang.reflect.InvocationTargetException
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at java.instrument/sun.instrument.InstrumentationImpl.loadClassAndStartAgent(InstrumentationImpl.java:513)
        at java.instrument/sun.instrument.InstrumentationImpl.loadClassAndCallPremain(InstrumentationImpl.java:525)
Caused by: java.lang.IllegalStateException: Fail to load TtlAgent , cause: java.lang.UnsupportedOperationException: class redefinition failed: attempted to change superclass or interfaces
        at com.alibaba.ttl.threadpool.agent.TtlAgent.premain(Unknown Source)
        ... 6 more
Caused by: java.lang.UnsupportedOperationException: class redefinition failed: attempted to change superclass or interfaces
        at java.instrument/sun.instrument.InstrumentationImpl.retransformClasses0(Native Method)
        at java.instrument/sun.instrument.InstrumentationImpl.retransformClasses(InstrumentationImpl.java:167)
        at com.alibaba.ttl.threadpool.agent.TtlAgent.premain(Unknown Source)
        ... 6 more
*** java.lang.instrument ASSERTION FAILED ***: "result" with message agent load/premain call failed at ./src/java.instrument/share/native/libinstrument/JPLISAgent.c line: 422
FATAL ERROR in native method: processing of -javaagent failed, processJavaStart failed
[1]    68385 abort      java -javaagent:src/main/agentdic/skywalking/skywalking-agent.jar  -jar