最近我们线上有同学反馈，java 服务在接入了支持预发的 javaagent 以后会出现缓存的内存增长，去掉 agent 启动以后内存增长正常。于是分析了一下这个问题，写了这篇文章。
备注：JVM 堆内存最大 1000M
主要会涉及下面这些内容：
- JVM native 内存分析的通用方法
- JVM Bootstrap ClassLoader 源码分析
- gdb 的一些调试技巧
- bytebuddy 打破双亲委派的类加载器
- 不好好干好日志的本分，处处恶心第一名的 log4j2 是如何处理错误堆栈的
背景介绍
线上全链路预发支持不能只支持 http 接口，还得支持 dubbo rpc、rocketmq、httpclient 等。
- http：针对 http 调用，都会添加一个流量标识的 header：x-ccloud-pre （1-预发流量 2-正式流量），可以支持okhttp、okhttp3、httpclient 4.x、Spring RestTemplate
- dubbo：预发实例都会增加一个
dubbo.provider.group=gray的参数，通过 group 来区分正式/预发的 provider，agent 内部实现根据流量标识来过滤 provider 的逻辑，并且通过 attachment 把流量标识往下游服务透传。 - RocketMQ：生产者只向本环境的 MQ 投递消息，消费者只消费本环境 MQ，原理就是根据是否是预发流量，如果是预发请求则将要投递的 topic 修改为预发的 topic。
以上实现都是通过一个 javaagent 来实现的，以实现业务方零代码修改接入。
分析过程
首先确认过不是堆内存的问题，因此需要用上 NativeMemoryTracking 来分析 native 内存，于是加上 -XX:NativeMemoryTracking=detail。但是只有这一个工具还不够，还需要结合 pmap、tcmalloc、jemalloc 来分析。因为内存增长缓慢，这里开启了一个后台定期执行 pmap 的脚本，用来分析内存增长在那一块内存区域内，然后放在哪里跑一晚上。
while true
do
sleep 900
name=`date "%Y_%m_%d_%H_%M_%S"`
echo $name
pmap -x 72 > "pmap_$name.out"
done
通过 diff 对比分析，找到了内存缓存增长的区域，随后 dump 出这一块内存，dump 的方式可以通过 gdb，也可以通过读取 /proc/$pid/mem 的方式来实现。
通过 dump 出来的内存，首先通过 strings 命令看看里面有没有认识的字符串。
很快发现里面有很多我们熟悉的类，比如：com.cvte.psd.pr.agent.rocketmq.consumer.push.RocketMqListenerOrderlyWrapperCreator$RocketListenerOrderlyWrapper，这个内部类实现了org.apache.rocketmq.client.consumer.listener.MessageListenerOrderly接口，请记住这个接口，后面会频繁出现。
RocketListenerOrderlyWrapper 做的事情也很简单，就是对 mq 消息处理进行了代理处理。RocketListenerOrderlyWrapper 实现如下：
import org.apache.rocketmq.client.consumer.listener.MessageListenerOrderly;
public class RocketMqListenerOrderlyWrapperCreator implements PreReleaseWrapperCreator<MessageListenerOrderly> {
public static class RocketListenerOrderlyWrapper implements MessageListenerOrderly {
private MessageListenerOrderly originListener;
private PreReleaseManager preReleaseManager;
public RocketListenerOrderlyWrapper(MessageListenerOrderly originListener, PreReleaseManager preReleaseManager) {
this.originListener = originListener;
}
@Override
public ConsumeOrderlyStatus consumeMessage(List<MessageExt> msgs, ConsumeOrderlyContext context) {
// ...
}
}
}
这个类就是用来包装 RocketMQ 的消息，来实现预发特性的。
上面 dump 出来的内容到底都是字符串，还是 class 文件的常量池的一部分呢？通过 16 进制分析工具可以进一步分析。把上面的 dump 文件导入到 010 Editor（https://www.sweetscape.com/010editor/ ）中，搜索 java 字节码的魔数（0xCAFEBABE），可以看这个这段内存中有 2.6W 个 class 文件。
可以删掉第一个 0xCAFEBABE 前面的字节，把剩下的文件当做 class 文件解析。
为什么会有这么多类文件出现在 native 内存中呢？通过 nmt 可以进一步辅助分析。这里可以看到类加载相关的内存 malloc 有 597M 左右，虽然 malloc 不代表真实的使用量（可能 malloc 以后不写，或者用完 free），这个值这么大还是不太正常。
接下来用 arthas 注入 rocketmq 消费相关的逻辑，发现 agent 中的一个 matches 方法抛出了 IllegalStateException 异常，提示找不到这个类型 org.apache.rocketmq.client.consumer.listener.MessageListenerConcurrently 的类型描述符。
这个 matches 调用是谁调用的呢？通过 arthas 的 stack 命令可以看到是 log4j2 打印日志中产生的调用。
代码语言：javascript复制ts=2022-11-10 10:51:49;thread_name=Log4j2-TF-1-AsyncLogger[AsyncContext@18b4aac2]-1;id=2c;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@18b4aac2
@com.cvte.psd.pr.agent.PreReleaseAgent$TypeMatcherWrapper.matches()
at com.cvte.psd.pr.agent.shaded.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer.doTransform(AgentBuilder.java:10304)
at com.cvte.psd.pr.agent.shaded.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer.transform(AgentBuilder.java:10263)
at com.cvte.psd.pr.agent.shaded.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer.transform(AgentBuilder.java:10186)
at sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:428)
at java.lang.ClassLoader.findBootstrapClass(ClassLoader.java:-2)
at java.lang.ClassLoader.findBootstrapClassOrNull(ClassLoader.java:1015)
at java.lang.ClassLoader.loadClass(ClassLoader.java:413)
at java.lang.ClassLoader.loadClass(ClassLoader.java:411)
at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:349)
at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
at org.apache.logging.log4j.core.impl.ThrowableProxyHelper.loadClass(ThrowableProxyHelper.java:209)
at org.apache.logging.log4j.core.impl.ThrowableProxyHelper.toExtendedStackTrace(ThrowableProxyHelper.java:114)
at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:38)
...
at com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:168)
at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:125)
at java.lang.Thread.run(Thread.java:748)
通过 ThrowableProxyHelper.toExtendedStackTrace 函数的进一步 watch，可以得到抛出的异常堆栈是什么。
method=org.apache.logging.log4j.core.impl.ThrowableProxyHelper.toExtendedStackTrace location=AtExit
ts=2022-11-10 15:22:42; [cost=3.189125ms] result=@ArrayList[
@Object[][
@ThrowableProxy[com.wosee.masaike.common.exception.BaseException: 设备：122222222 未获取到绑定信息],
],
@ExtendedStackTraceElement[][
[com.wosee.iot.xxx.UcpDeviceService.getOrgCodeByDeviceId(UcpDeviceService.java:111) ~[app.jar:1.3.2-SNAPSHOT]],
...
[com.wosee.iot.xxx.RocketMqListener.consumeMessage(RocketMqListener.java:35)
[com.cvte.psd.pr.agent.rocketmq.consumer.push.RocketMqListenerOrderlyWrapperCreator$RocketListenerOrderlyWrapper.consumeMessage(RocketMqListenerOrderlyWrapperCreator.java:44) ~[?:?]],
[org.apache.rocketmq.client.impl.consumer.ConsumeMessageOrderlyService$ConsumeRequest.run(ConsumeMessageOrderlyService.java:471)
...
]
可以看到是因为业务代码 mq 消费的 consumeMessage 代码使用 log4j2 打印了日志，在一些情况下会抛出 com.wosee.masike.common.exception.BaseException 业务异常。
问题 0：为什么要 load class
我们来看触发类加载的 org.apache.logging.log4j.core.impl.ThrowableProxy 类，
这个类有一个注释
A proxy is used to represent a throwable that may not exist in a different class loader or JVM. When an application deserializes a ThrowableProxy, the throwable may not be set, but the throwable's information is preserved in other fields of the proxy like the message and stack trace.
大意就是这个类为了实现异常信息可以跨网络传输，本地的 LogEvent 可能会传输给另外的 JVM，便于不同 JVM 可以识别这个异常，LogEvent 对日志事件做了封装，对异常做了一些扩展，添加了一些扩展信息，比如异常栈所属的 jar 包、版本等（普通的堆栈里没有打印这些）。
ThrowableProxyHelper.toExtendedStackTrace 是上述功能的具体实现。主要做了下面这些事情：
- 拿到方法所属的类，从类中获取 jar 包的位置和版本
- 因为异常栈中没有保存 class 对象，只有类名，因此需要做类加载。（当然也不是所有的都需要，这里有一个小优化不展开说）
这部分简化过的代码逻辑如下：
代码语言：javascript复制static ExtendedStackTraceElement[] toExtendedStackTrace(
final ThrowableProxy src,
final Stack<Class<?>> stack, final Map<String, CacheEntry> map,
final StackTraceElement[] rootTrace,
final StackTraceElement[] stackTrace) {
int stackLength;
final ExtendedStackTraceElement[] extStackTrace = new ExtendedStackTraceElement[stackLength];
Class<?> clazz = stack.isEmpty() ? null : stack.peek();
ClassLoader lastLoader = null;
// 遍历堆栈
for (int i = stackLength - 1; i >= 0; --i) {
final StackTraceElement stackTraceElement = stackTrace[i];
final String className = stackTraceElement.getClassName();
// The stack returned from getCurrentStack may be missing entries for java.lang.reflect.Method.invoke()
// and its implementation. The Throwable might also contain stack entries that are no longer
// present as those methods have returned.
ExtendedClassInfo extClassInfo;
final CacheEntry cacheEntry = map.get(className);
// 在缓存列表中直接返回
if (cacheEntry != null) {
final CacheEntry entry = cacheEntry;
extClassInfo = entry.element;
if (entry.loader != null) {
lastLoader = entry.loader;
}
} else {
// 不在则加载类，然后加入缓存列表
final CacheEntry entry = toCacheEntry(ThrowableProxyHelper.loadClass(lastLoader, className), false);
extClassInfo = entry.element;
map.put(className, entry);
if (entry.loader != null) {
lastLoader = entry.loader;
}
}
extStackTrace[i] = new ExtendedStackTraceElement(stackTraceElement, extClassInfo);
}
return extStackTrace;
}
只有在需要获取额外的异常堆栈信息时，才会触发这里的逻辑，正常的打日志是不会出现的。
比如
代码语言：javascript复制logger.error(e);
logger.error("happened service exception! message:{}", e);
第一种方式的输出是
代码语言：javascript复制[2022-11-15 08:04:43.316][main][ERROR][com.github.shehanperera.example.MyTest] java.lang.IllegalArgumentException: Object varargs must not be null
这里不需要堆栈信息，不会触发类加载
第二种方式的输出
代码语言：javascript复制java.lang.IllegalArgumentException: Object varargs must not be null
at org.apache.commons.lang3.StringUtils.joinWith(StringUtils.java:4880) ~[commons-lang3-3.12.0.jar:3.12.0]
at com.cvte.ya.MyTest.main(MyTest.java:36) [classes/:?]
这种情况下就会触发类加载获取额外的信息，比如这里的 commons-lang3-3.12.0.jar:3.12.0。
这里看起来没什么毛病，但是为什么会提示找不到 org.apache.rocketmq.client.consumer.listener.MessageListenerOrderly这个接口明明是在业务 jar 中是存在的。
通过上面的调用堆栈可以发现上面的类加载中，最终类的加载被委托到最顶层的 Bootstrap ClassLoader。
这里的逻辑就比较清楚了，当初始化类的时候，发现其父类还没有进行过初始化，则需要先触发其父类的初始化。org.apache.rocketmq...MessageListenerOrderly 这个接口的加载被触发是因为需要加载实现类 com.cvte...RocketMqListenerOrderlyWrapperCreatorRocketListenerOrderlyWrapper。而且可以推断：com.cvte...RocketMqListenerOrderlyWrapperCreatorRocketListenerOrder 这个内部类在内存中加载成功了，通过 jvm 解析这个类的字节码，发现它实现了 org.apache.rocketmq...MessageListenerOrderly 接口，于是去尝试加载这个接口但是失败了。
这里就有四个奇怪的问题：
- 为什么
RocketMqListenerOrderlyWrapperCreator$RocketListenerOrderlyWrapper是由 Bootstrap ClassLoader 去加载的 - 为什么
org.apache.rocketmq...MessageListenerOrderly接口加载失败了 - 为什么会导致 native 内存上涨
- 为什么 agent 的功能还是正常的
问题 1：为什么由 Bootstrap ClassLoader 去加载
这就要再看看双亲委派相关的知识，引用《深入理解 Java 虚拟机》这本书的原话：
双亲委派模型的工作过程是：如果一个类加载器收到了类加载的请求，它首先不会自己去尝试加载这个类，而是把这个请求委派给父类加载器去完成，每一个层次的类加载器都是如此，因此所有的加载请求最终都应该传送到最顶层的启动类加载器中，只有当父加载器反馈自己无法完成这个加载请求（它的搜索范围中没有找到所需的类）时，子加载器才会尝试自己去完成加载。
JVM中内置了三个重要的 ClassLoader，分别是 BootstrapClassLoader、ExtensionClassLoader 和 AppClassLoader
这部分源码非常简单，就是一个递归查询。
代码语言：javascript复制protected Class<?> loadClass(String name, boolean resolve)
throws ClassNotFoundException
{
synchronized (getClassLoadingLock(name)) {
// First, check if the class has already been loaded
Class<?> c = findLoadedClass(name);
if (c == null) {
try {
if (parent != null) { // 当父类加载器存在时，交给父类去加载
c = parent.loadClass(name, false);
} else { // 父类加载为空时，交给 Bootstrap
c = findBootstrapClassOrNull(name);
}
} catch (ClassNotFoundException e) {
// 如果父类加载器们抛出了 ClassNotFoundException 异常
// 说明父类加载无法完成加载
}
if (c == null) {
// 当父类加载无法加载时
// 再调用本身的 findClass 来进行类加载
c = findClass(name);
}
}
if (resolve) {
resolveClass(c);
}
return c;
}
}
从上面的堆栈可以看出，加载 com.cvte...RocketMqListenerOrderlyWrapperCreator$RocketListenerOrderlyWrapper 类确实使用了双亲委派，经过好几次父类加载器的加载失败，委托给了 Bootstrap。
理论上来说 javaagent 的 jar 不会出现 Bootstrap 类加载器的 classpath 搜索列表里，后面去看了一下 javaagent 的代码，确实我们为了注入 java 的内部类（线程池等），agent 的 jar 包需要被 Bootstrap 类加载器加载，否则 Bootstrap 类加载器就找不到 javaagent 中的类了。
代码语言：javascript复制public class AgentMain {
public static void premain(String agentArguments, Instrumentation instrumentation) {
try {
final File agentJarFile = getAgentJarFile();
try (JarFile jarFile = new JarFile(agentJarFile)) {
// 将 agent 的 jar 包加入到 BootstrapClassLoader
instrumentation.appendToBootstrapClassLoaderSearch(jarFile);
}
} catch (Exception e) {
System.err.println("Failed to start agent");
}
}
}
到这里就搞清楚了第一个问题，因为 agent 的 jar 被加入 Bootstrap 的 classpath 路径，又因为双亲委派，导致 Bootstrap ClassLoader 加载成功了 com.cvte...RocketMqListenerOrderlyWrapperCreator$RocketListenerOrderlyWrapper。
问题 2：为什么 org.apache.rocketmq...MessageListenerOrderly 接口加载失败了
众所周知，Bootstrap ClassLoader 是由 C 实现的，这个类加载器负责加载存放在 <JAVA_HOME>lib 目录，或者被 -Xbootclasspath 参数所指定的路径中存放的 jar 文件。上面提到在 premain 中我们把 javaagent 自己的 jar 加入到了 Bootstrap 的 classpath，使得 javaagent 中的 com.cvte...RocketMqListenerOrderlyWrapperCreator$RocketListenerOrderlyWrapper 可以被加载，但是 javaagent 中不会将 rocketmq 的 jar 打包到自己的 jar 中，而是采用 provided 的方式，由使用方提供。
<dependency>
<groupId>org.apache.rocketmq</groupId>
<artifactId>rocketmq-client</artifactId>
<version>4.7.0</version>
<scope>provided</scope>
</dependency>
也就是说包含了 org.apache.rocketmq...MessageListenerOrderly 接口的 rocketmq-client-4.7.0.jar 这个 jar 并不会被加入到 Bootstrap 的 classpath 中，因此 MessageListenerOrderly 接口加载失败， 因为实现的接口加载失败，导致 jvm 认为 com.cvte...RocketMqListenerOrderlyWrapperCreator$RocketListenerOrderlyWrapper 加载失败。
问题 3：为什么 native 内存会增长
看到这里，可能很多人已经大概知道是为什么了，先说结论：
Bootstrap ClassLoader 是 C 实现的，会把 RocketListenerOrderlyWrapper 文件加载到 native 内存中，然后进行解析，一般来说，Bootstrap ClassLoader 要加载的类，要么加载成功，要么不存在不需要加载。如果加载成功则会将类写入到一个全局的 hashmap 中，下次要加载时直接返回，不用重复解析类文件。
但是这里的情况有点特殊，RocketListenerOrderlyWrapper 类加载失败了，但是加载过程产生的 native 内存不会被释放。又因为业务一直在抛异常导致 RocketListenerOrderlyWrapper 类一直尝试被加载，但是没有一次能成功，导致 native 内存持续上涨。
接下来我们用 gdb 调试的方式来验证上面的过程。
首先在 ClassLoader::load_classfile 函数打一个断点，可以看到这里的逻辑是遍历Bootstrap ClassLoader 的 classpath 尝试加载 com.cvte...RocketMqListenerOrderlyWrapperCreator$RocketListenerOrderlyWrapper 类。
跟进 ClassPathEntry.open_stream 方法，因为是一个最终进入到了 ClassPathZipEntry::open_stream 中，这个方法从 jar 中读取文件，写入到 buffer 开始的地址中。
通过 x 命令也可以看到 class 文件的魔数，确实加载成功了一个 class 文件。
这块内存确实是 native 内存管理的，我们可以通过地址去 pmap 中反向查找。
我写了一个小工具 pmapx，来查某个地址处于什么内存地址段区间中，还可以 dump 内存到文件，还可以在内存中搜索 16 进制或者字符串，这个工具后面会释放出来。
代码语言：javascript复制$ pmapx --type range --pid `pidof java` --addr 0x7f2f98230198 | grep -C 10 0x7f2f98230198
可以看到这块内存是属于典型的 Linux malloc 64M 内存区域（59808 5728=65536KB）。
到这里，我们可以看到 com/cvte/psd/pr/agent/rocketmq/consumer/push/RocketMqListenerConcurrentlyWrapperCreator$RocketListenerConcurrentlyWrapper.class 被加载到内存中，接下来就是进行类文件解析了。
在 ClassFileParser::parseClassFile 上打一个断点。
这里的 cfs 是 ClassFileStream 类型的指针，ClassFileStream 内部包裹了我们上面加载的类文件内存指针 buffer。
代码语言：javascript复制ClassFileStream* cfs = stream();
class ClassFileStream: public ResourceObj {
private:
u1* _buffer_start; // Buffer bottom
u1* _buffer_end; // Buffer top (one past last element)
u1* buffer() const { return _buffer_start; }
}
接下来就是开始解析字节码，判断魔数、版本、常量池等。
随后进入到接下接口的环节，这里的接口数量为 1，解析到 interface 的类名以后会尝试去加载。
接下来调用 SystemDictionary::resolve_instance_class_or_null 来尝试加载 org/apache/rocketmq/client/consumer/listener/MessageListenerConcurrently 接口，最后走到了 ClassLoader::load_classfile 来尝试加载 org/apache/rocketmq/client/consumer/listener/MessageListenerConcurrently.class 文件，通过 stream 值我们可以发现，确实在 Bootstrap ClassLoader 中没有找到这个 class 文件。
调用堆栈为
至此，native 内存增长的原因也比较清楚了，Bootstrap ClassLoader 每次都被触发读取 com.cvte...RocketMqListenerOrderlyWrapperCreator$RocketListenerOrderlyWrapper.class 字节码到内存中，但是因为依赖的接口加载失败，导致整体加载失败，不会被写入到 SystemDictionary 的全局 hashmap，导致每次都要重新加载写入新的 native 内存。
这个过程如下所示。
验证想法
把 log4j 的日志级别设置为 off 就可以来验证这个问题。
修改以后继续压测内存占用果然稳如老狗，如下图所示。
问题 4：为什么预发 agent 的功能还是正常的
这里就要提一下 bytebuddy 的类加载逻辑，bytebuddy 封装了几个常用的 ClassLoader
- ByteArrayClassLoader：byte buddy自定义类加载器，继承自ClassLoader，未重写 loadClass 方法，符合双亲委派模式
- ByteArrayClassLoader$ChildFirst: ChildFirst 继承了ByteArrayClassLoader，但是重写了 loadClass 方法，破坏了双亲委派模式。
ChildFirst 类加载的源码如下：
代码语言：javascript复制public static class ChildFirst extends ByteArrayClassLoader {
protected Class<?> loadClass(String name, boolean resolve) throws ClassNotFoundException {
// 如果已加载直接返回
Class<?> type = findLoadedClass(name);
if (type != null) {
return type;
}
try {
// 如果没有加载，则先自己尝试查找，打破双亲委派
type = findClass(name);
if (resolve) {
resolveClass(type);
}
return type;
} catch (ClassNotFoundException exception) {
// If an unknown class is loaded, this implementation causes the findClass method of this instance
// to be triggered twice. This is however of minor importance because this would result in a
// ClassNotFoundException what does not alter the outcome.
// 自己实在找不到，就交给父类
return super.loadClass(name, resolve);
}
}
}
com.cvte.psd.pr.agent.rocketmq.consumer.push.RocketMqListenerOrderlyWrapperCreator$RocketListenerOrderlyWrapper正是由ByteArrayClassLoader$ChildFirst这个 classloader 加载的。这个可以通过堆内存 dump 来确认。
ByteArrayClassLoader$ChildFirst 打破了双亲委派，不会先将类委托给 Bootstrap ClassLoader，也就不会出现问题，javaagent 功能一切正常。
至此，问题分析结束。
如何解决
- 修改 jvm 解决native 内存「泄露」
- 修改 log4j 去掉 ThrowableProxy toExtendedStackTrace 没什么用的逻辑
