背景

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

MSE发起了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-15 06:22:47 [oneagent plugin arms-agent start] ERROR c.a.o.plugin.PluginManagerImpl -start plugin error, name: arms-agent
com.alibaba.oneagent.plugin.PluginException: start error, agent jar::/home/admin/.opt/ArmsAgent/plugins/ArmsAgent/arms-bootstrap-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 omitted
2022-06-16 09:51:09 [oneagent plugin ahas-java-agent start] ERROR c.a.o.plugin.PluginManagerImpl -start plugin error, name: ahas-java-agent
com.alibaba.oneagent.plugin.PluginException: start error, agent jar::/home/admin/.opt/ArmsAgent/plugins/ahas-java-agent/ahas-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的方法入口添加日志：

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

没有报错的时候，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不是线程安全的？

查了下文档（ https://pubs.opengroup.org/onlinepubs/009695399/functions/xsh_chap02_09.html ），发现stat是线程安全的。

于是又回过头来再看，这时候注意到stat的路径是不正常的：有的时候路径是空，有的时候路径是/home/admin/.opt/ArmsAgent/plugins/ahas-java-agent/ahas-java-agent.jarSHOT.jar，从字符末尾可以看到，基本上是因为两个字符写到了同一片内存导致的；而且对应字符串长度也变成了一个不规律的数字了。

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

字符编码转换有问题？

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

结果发现，在Linux下，utf8ToPlatform就是直接memcpy，而且memcpy的目标地址是在栈上。

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

后来仔细查了下，发现和环境变量有关，ECS上编码相关的环境变量是LANG=en_US.UTF-8，在容器上centos:7默认没有这个环境变量，此种情况下，jvm读到的是ANSI_X3.4-1968。
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的文档，发现它不是完全线程安全的：

通俗的说，iconv之前，需要先用iconv_open打开一个iconv_t，而且这个iconv_t，不支持多线程同时使用。

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

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

如何修复

先修复one-java-agent

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

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

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

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

jvm要不要修复

然后我们分析下jvm侧的代码，发现就是因为iconv_t不是线程安全的，导致appendToClassLoaderSearch0方法不是线程安全的，那能不能优雅的解决掉呢？

如果是Java程序，直接用ThreadLoal来存储iconv_t就能解决了。

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

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

pthread_key_create创建thread-local storage区域
pthread_setspecific用于将值放入thread-local storage
pthread_getspecific用于从thread-local storage取出值
最重要的，pthread_once满足了pthread_key_t只能初始化一次的需求。
另外也需要提到的，pthread_once的第二个参数，就是线程结束时的回调，我们就可以用它来关闭iconv_t，避免资源泄漏。

总之pthread提供了thread_local的全生命周期管理。于是，最终代码如下，用make_key初始化thread-local storage：

于是编译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
●dragonwell修复的链接 https://github.com/alibaba/dragonwell8/pull/346
●one-java-agent给大家带来了更加方便、无侵入的微服务治理方式 https://www.aliyun.com/product/aliware/mse

Java Agent踩坑之appendToSystemClassLoaderSearch问题

背景

问题

打日志、确定现场

分析代码

找不到对应的jar文件？

字符编码转换有问题？

iconv不是线程安全的！

如何修复

先修复one-java-agent

jvm要不要修复

微服务

热门文章

最新文章

相关课程

相关电子书

相关实验场景