写点什么

Java Agent 踩坑之 appendToSystemClassLoaderSearch 问题

  • 2023-02-07
    浙江
  • 本文字数:4258 字

    阅读完需:约 14 分钟

本文是《容器中的 Java》系列文章之 2/n,欢迎关注后续连载 :) 。


从 Java Agent 报错开始,到 JVM 原理,到 glibc 线程安全,再到 pthread tls,逐步探究 Java Agent 诡异报错。

背景

由于阿里云多个产品都提供了 Java Agent 给用户使用,在多个 Java Agent 一起使用的场景下,造成了总体 Java Agent 耗时增加,各个 Agent 各自存储,导致内存占用、资源消耗增加。


所以我们发起了 one-java-agent 项目,能够协同各个 Java Agent;同时也支持更加高效、方便的字节码注入。


其中,各个 Java Agent 作为 one-java-agent 的 plugin,在 premain 阶段是通过多线程启动的方式来加载,从而将启动速度由 O(n) 降低到 O(1),降低了整体 Java Agent 整体的加载时间。

问题

但最近在新版 Agent 验证过程中,one-java-agent 的 premain 阶段,发现有如下报错:


2022-06-16 09:51:09 [oneagent plugin a-java-agent start] ERROR c.a.o.plugin.PluginManagerImpl -start plugin error, name: a-java-agentcom.alibaba.oneagent.plugin.PluginException: start error, agent jar::/path/to/one-java-agent/plugins/a-java-agent/a-java-agent-1.7.0-SNAPSHOT.jar  at com.alibaba.oneagent.plugin.TraditionalPlugin.start(TraditionalPlugin.java:113)  at com.alibaba.oneagent.plugin.PluginManagerImpl.startOnePlugin(PluginManagerImpl.java:294)  at com.alibaba.oneagent.plugin.PluginManagerImpl.access$200(PluginManagerImpl.java:22)  at com.alibaba.oneagent.plugin.PluginManagerImpl$2.run(PluginManagerImpl.java:325)  at java.lang.Thread.run(Thread.java:750)Caused by: java.lang.InternalError: null  at sun.instrument.InstrumentationImpl.appendToClassLoaderSearch0(Native Method)  at sun.instrument.InstrumentationImpl.appendToSystemClassLoaderSearch(InstrumentationImpl.java:200)  at com.alibaba.oneagent.plugin.TraditionalPlugin.start(TraditionalPlugin.java:100)  ... 4 common frames omitted2022-06-16 09:51:09 [oneagent plugin b-java-agent start] ERROR c.a.o.plugin.PluginManagerImpl -start plugin error, name: b-java-agentcom.alibaba.oneagent.plugin.PluginException: start error, agent jar::/path/to/one-java-agent/plugins/b-java-agent/b-java-agent.jar  at com.alibaba.oneagent.plugin.TraditionalPlugin.start(TraditionalPlugin.java:113)  at com.alibaba.oneagent.plugin.PluginManagerImpl.startOnePlugin(PluginManagerImpl.java:294)  at com.alibaba.oneagent.plugin.PluginManagerImpl.access$200(PluginManagerImpl.java:22)  at com.alibaba.oneagent.plugin.PluginManagerImpl$2.run(PluginManagerImpl.java:325)  at java.lang.Thread.run(Thread.java:855)Caused by: java.lang.IllegalArgumentException: null  at sun.instrument.InstrumentationImpl.appendToClassLoaderSearch0(Native Method)  at sun.instrument.InstrumentationImpl.appendToSystemClassLoaderSearch(InstrumentationImpl.java:200)  at com.alibaba.oneagent.plugin.TraditionalPlugin.start(TraditionalPlugin.java:100)  ... 4 common frames omitted
复制代码


熟悉 Java Agent 的同学可能能注意到,这是调用 Instrumentation.appendToSystemClassLoaderSearch 报错了。


但首先 appendToSystemClassLoaderSearch 的路径是存在的;其次,这个报错的真实原因是在 C++ 部分,比较难排查。


但不管怎样,还是要深究下为什么出现这个错误。


首先我们梳理下具体的调用流程,下面的分析都是基于此来分析的(当然,这些图也是解决了问题后,逆向推导出来的):


- Instrumentation.appendToSystemClassLoaderSearch (java)  - appendToClassLoaderSearch0 (JNI)     `- appendToClassLoaderSearch         |- AddToSystemClassLoaderSearch         |  `-create_class_path_zip_entry         |      `-stat         `-convertUft8ToPlatformString            `- iconv
复制代码

打日志、确定现场

因为这个问题在容器环境下,有 10% 的概率出现,比较容易复现,于是就用 dragonwell8 的最新代码,加日志,确认下现场。


首先在 JNI 的实际入口处,也就是 appendToClassLoaderSearch 的方法入口添加日志:


1.png


加了上面的日志后,发现问题更加令人头秃了:


  • 没有报错的时候,appendToClassLoaderSearch entry 会输出。

  • 有报错的时候,appendToClassLoaderSearch entry 反而没有输出。难道是没执行到这儿?


这个和报错的日志对不上啊,难道是 stacktrace 信息骗了我们?


过了难熬的一晚上后,第二天请教了 dragonwell 的同学,大佬打日志的姿势是这样的:


  • tty->print_cr("internal error");

  • 如果上面用不了,再用 printf("xxx\n");fflush(stdout);


这样加日志后,果然我们的日志都能打出来了。


这是踩的第一个坑,printf 要加上 fflush 才能保证输出成功

分析代码

后面又是不断加日志,最终发现原因是 create_class_path_zip_entry 返回 NULL。

找不到对应的 jar 文件?

继续排查,发现是 stat 报错,返回 No such file or directory。但是前面也提到了,jarFile 的路径是存在的,难道 stat 不是线程安全的?


查了下 stat 相关文档 [ 1] ,发现 stat 系统调用是线程安全的。


于是又回过头来再看,这时候注意到 stat 的路径是不正常的:


有的时候路径是空,有的时候路径是 /path/to/b-java-agent/b-java-agent.jarSHOT.jar,从字符末尾可以看出,基本上是因为两个字符写到了同一片内存导致的;而且对应字符串长度也变成了一个不规律的数字了。


那么问题就很明确了,开始查找这个字符串的生成。这个字符是 convertUft8ToPlatformString 生成的。

字符编码转换有问题?

于是开始调试 utf8ToPlatform 的逻辑,这时候为了避免频繁加日志、编译、重启容器,所以直接在 ECS 上运行 gdb 来调试 jvm。


结果发现,在 Linux 下,utf8ToPlatform 就是直接 memcpy,而且 memcpy 的目标地址是在栈上分配的:


2.png


这怎么看都不太可能有线程安全问题啊?


后来仔细查了下,发现和环境变量有关,ECS 上编码相关的环境变量是 LANG=en_US.UTF-8;而在在容器上,centos:7 默认没有这个环境变量,此种情况下,jvm 读到的是 ANSI_X3.4-1968。


这一块可以参考下 nl_langinfo(CODESET)的文档:https://man7.org/linux/man-pages/man3/nl_langinfo.3.html


这儿是第二个坑,环境变量会影响本地编码转换


结合如上现象和代码,发现在容器环境下,还是要经过 iconv,从 UTF-8 转到 ANSI_X3.4-1968 编码的。


其实,这儿也可以推测出来,如果手动在容器中设置了 LANG=en_US.UTF-8,这个问题就不会再出现。额外的验证也证实了这点。


言归正传,然后又加日志,最终确认是 iconv 的时候,目标字符串写乱掉了。


难道是 iconv 线程不安全?

iconv 不是线程安全的!

查一下 iconv 的文档,发现它不是完全线程安全的:


3.png


解释一下就是,iconv 之前,需要先用 iconv_open 打开一个 iconv_t,而且这个 iconv_t,不支持多线程同时使用。


至此,问题已经差不多定位清楚了:因为 jvm 把 iconv_t 写成了全局变量,这样在多个线程同时调用 appendToClassLoaderSearch0 的时候,就有可能同时调用 iconv,导致竞态问题,把字符串写乱掉。


这儿是第三个坑,iconv 不是线程安全的

如何修复

先修复 one-java-agent

对于 Java 代码,非常容易修改,只需要加一个锁就可以了:


4.png


但是这儿有一个设计问题,instrument 对象已经在代码中到处散落了,现在突然要加一个锁,几乎所有用到的地方都要改,代码改造成本比较大。


于是最终还是通过 proxy 类来解决:


5.png


这样其他地方就只需要使用 InstrumentationWrapper 就可以了,也不会触发这个问题。


Java 9+ 的处理


但是注意到,在 JDK9 中,Instrumentation 这个接口增加了 redefineModule/isModifiableModule 方法,在新版本 JVM 下,上图中的 InstrumentationWrapper 就会因为没有这两个方法而报错。


本质上,是 JDK 对 Instrumentation 这个 interface 做了不兼容的修改,这个改动就很难通过手动 proxy 的方式来兼容。


于是只能使用 JDK Proxy 来实现了,主要代码如图:


6.png


这样 one-java-agent 总算完整的修完了这个 bug 了。

jvm 要不要修复

然后我们分析下 jvm 侧的代码,发现其实就是因为 iconv_t 不是线程安全的,导致 appendToClassLoaderSearch0 方法不是线程安全的,那能不能优雅的解决掉这个问题呢?


如果是 Java 程序,我们可以直接用 ThreadLoal 来存储 iconv_t,就能解决这个问题。


但是 cpp 这边,虽然 C++ 11 支持 thread_local,但首先 jdk8 还没用 C++ 11(这个可以参考 JEP 347 [2 ] );其次,C++ 11 的也仅仅支持 thread_local 的 set 和 get,thread_local 的初始化、销毁等生命周期管理还不支持,比如没办法在线程结束时自动回收 iconv_t 资源。


那咱们就 fallback 到 pthread?因为 pthread 提供了 thread-specific data,可以做类似的事情。


  1. pthread_key_create 创建 thread-local storage 区域

  2. pthread_setspecific 用于将值放入 thread-local storage

  3. pthread_getspecific 用于从 thread-local storage 取出值

  4. 最重要的,pthread_once 满足了 pthread_key_t 只能初始化一次的需求。

  5. 另外也需要提到的,pthread_once 的第二个参数就是线程结束时的回调,我们就可以用它来关闭 iconv_t,避免资源泄漏。


总结一下就是,pthread 提供了 thread_local 的全生命周期管理。


于是,最终代码如下,用 pthread_once 初始化 thread-local storage,然后每个线程分配一个 iconv_t:


7.png


8.png


接下来,编译 JDK、打镜像、批量重启数次 pod 验证,就没有再出现文章开头提到的问题了。

总结

在整个过程中,我们从 Java 到 JNI/JVMTi,再到 glibc,再到 pthread,踩了很多坑:


  • printf 要加上 fflush 才能保证输出成功

  • 环境变量会影响本地字符编码转换

  • iconv 不是线程安全的

  • 使用 pthread thread-local storage 来实现线程局部变量的全生命周期管理


从这个案例中,沿着调用栈、代码,逐步还原问题、并修复问题,希望大家能通过这个案例,对 Java/JVM 多了解一点。

参考资料

one-java-agent 修复的链接:


https://github.com/alibaba/one-java-agent/issues/31


dragonwell8 修复的链接:


https://github.com/alibaba/dragonwell8/pull/346


[1] stat 相关文档:


https://pubs.opengroup.org/onlinepubs/009695399/functions/xsh_chap02_09.html


[2] JEP 347:


https://openjdk.org/jeps/347

发布于: 刚刚阅读数: 5
用户头像

云原生技术是云时代释放云价值的最短路径。 2020-06-11 加入

还未添加个人简介

评论

发布
暂无评论
Java Agent 踩坑之 appendToSystemClassLoaderSearch 问题_Java_阿里巴巴中间件_InfoQ写作社区