一次想不到的Bootstrap类加载器带来的Native内存

　　最近我们线上有同学反馈，java服务在接入了支持预发的javaagent以后会出现缓存的内存增长，去掉agent启动以后内存增长正常。于是分析了一下这个问题，写了这篇文章。
　　备注：JVM堆内存最大1000M
　　主要会涉及下面这些内容：JVMnative内存分析的通用方法JVMBootstrapClassLoader源码分析gdb的一些调试技巧bytebuddy打破双亲委派的类加载器不好好干好日志的本分，处处恶心第一名的log4j2是如何处理错误堆栈的背景介绍
　　线上全链路预发支持不能只支持http接口，还得支持dubborpc、rocketmq、httpclient等。http：针对http调用，都会添加一个流量标识的header：xccloudpre（1预发流量2正式流量），可以支持okhttp、okhttp3、httpclient4。x、SpringRestTemplatedubbo：预发实例都会增加一个dubbo。provider。groupgray的参数，通过group来区分正式预发的provider，agent内部实现根据流量标识来过滤provider的逻辑，并且通过attachment把流量标识往下游服务透传。RocketMQ：生产者只向本环境的MQ投递消息，消费者只消费本环境MQ，原理就是根据是否是预发流量，如果是预发请求则将要投递的topic修改为预发的topic。
　　以上实现都是通过一个javaagent来实现的，以实现业务方零代码修改接入。分析过程
　　首先确认过不是堆内存的问题，因此需要用上NativeMemoryTracking来分析native内存，于是加上XX：NativeMemoryTrackingdetail。但是只有这一个工具还不够，还需要结合pmap、tcmalloc、jemalloc来分析。因为内存增长缓慢，这里开启了一个后台定期执行pmap的脚本，用来分析内存增长在那一块内存区域内，然后放在哪里跑一晚上。whiletruedosleep900namedateYmdHMSechonamepmapx72pmapname。outdone复制代码
　　通过diff对比分析，找到了内存缓存增长的区域，随后dump出这一块内存，dump的方式可以通过gdb，也可以通过读取procpidmaps的方式来实现。
　　通过dump出来的内存，首先通过strings命令看看里面有没有认识的字符串。
　　很快发现里面有很多我们熟悉的类，比如：com。cvte。psd。pr。agent。rocketmq。consumer。push。RocketMqListenerOrderlyWrapperCreatorRocketListenerOrderlyWrapper，这个内部类实现了org。apache。rocketmq。client。consumer。listener。MessageListenerOrderly接口，请记住这个接口，后面会频繁出现。
　　RocketListenerOrderlyWrapper做的事情也很简单，就是对mq消息处理进行了代理处理。RocketListenerOrderlyWrapper实现如下：importorg。apache。rocketmq。client。consumer。listener。MessageListenerOrderly；publicclassRocketMqListenerOrderlyWrapperCreatorimplementsPreReleaseWrapperCreatorMessageListenerOrderly｛publicstaticclassRocketListenerOrderlyWrapperimplementsMessageListenerOrderly｛privateMessageListenerOrderlyoriginListener；privatePreReleaseManagerpreReleaseManager；publicRocketListenerOrderlyWrapper（MessageListenerOrderlyoriginListener，PreReleaseManagerpreReleaseManager）｛this。originListeneroriginListener；｝OverridepublicConsumeOrderlyStatusconsumeMessage（ListMessageExtmsgs，ConsumeOrderlyContextcontext）｛。。。｝｝｝复制代码
　　这个类就是用来包装RocketMQ的消息，来实现预发特性的。
　　上面dump出来的内容到底都是字符串，还是class文件的常量池的一部分呢？通过16进制分析工具可以进一步分析。把上面的dump文件导入到010Editor（www。sweetscape。com010editor）中，搜索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打印日志中产生的调用。ts2022111010：51：49；threadnameLog4j2TF1AsyncLogger〔AsyncContext18b4aac2〕1；id2c；isdaemontrue；priority5；TCCLsun。misc。LauncherAppClassLoader18b4aac2com。cvte。psd。pr。agent。PreReleaseAgentTypeMatcherWrapper。matches（）atcom。cvte。psd。pr。agent。shaded。bytebuddy。agent。builder。AgentBuilderDefaultExecutingTransformer。doTransform（AgentBuilder。java：10304）atcom。cvte。psd。pr。agent。shaded。bytebuddy。agent。builder。AgentBuilderDefaultExecutingTransformer。transform（AgentBuilder。java：10263）atcom。cvte。psd。pr。agent。shaded。bytebuddy。agent。builder。AgentBuilderDefaultExecutingTransformer。transform（AgentBuilder。java：10186）atsun。instrument。InstrumentationImpl。transform（InstrumentationImpl。java：428）atjava。lang。ClassLoader。findBootstrapClass（ClassLoader。java：2）atjava。lang。ClassLoader。findBootstrapClassOrNull（ClassLoader。java：1015）atjava。lang。ClassLoader。loadClass（ClassLoader。java：413）atjava。lang。ClassLoader。loadClass（ClassLoader。java：411）atsun。misc。LauncherAppClassLoader。loadClass（Launcher。java：349）atjava。lang。ClassLoader。loadClass（ClassLoader。java：357）atorg。apache。logging。log4j。core。impl。ThrowableProxyHelper。loadClass（ThrowableProxyHelper。java：209）atorg。apache。logging。log4j。core。impl。ThrowableProxyHelper。toExtendedStackTrace（ThrowableProxyHelper。java：114）atorg。apache。logging。log4j。core。pattern。PatternFormatter。format（PatternFormatter。java：38）。。。atcom。lmax。disruptor。BatchEventProcessor。processEvents（BatchEventProcessor。java：168）atcom。lmax。disruptor。BatchEventProcessor。run（BatchEventProcessor。java：125）atjava。lang。Thread。run（Thread。java：748）复制代码
　　通过ThrowableProxyHelper。toExtendedStackTrace函数的进一步watch，可以得到抛出的异常堆栈是什么。methodorg。apache。logging。log4j。core。impl。ThrowableProxyHelper。toExtendedStackTracelocationAtExitts2022111015：22：42；〔cost3。189125ms〕resultArrayList〔Object〔〕〔ThrowableProxy〔com。wosee。masaike。common。exception。BaseException：设备：122222222未获取到绑定信息〕，〕，ExtendedStackTraceElement〔〕〔〔com。wosee。iot。xxx。UcpDeviceService。getOrgCodeByDeviceId（UcpDeviceService。java：111）〔app。jar：1。3。2SNAPSHOT〕〕，。。。〔com。wosee。iot。xxx。RocketMqListener。consumeMessage（RocketMqListener。java：35）〔com。cvte。psd。pr。agent。rocketmq。consumer。push。RocketMqListenerOrderlyWrapperCreatorRocketListenerOrderlyWrapper。consumeMessage（RocketMqListenerOrderlyWrapperCreator。java：44）〔？：？〕〕，〔org。apache。rocketmq。client。impl。consumer。ConsumeMessageOrderlyServiceConsumeRequest。run（ConsumeMessageOrderlyService。java：471）。。。〕复制代码
　　可以看到是因为业务代码mq消费的consumeMessage代码使用log4j2打印了日志，在一些情况下会抛出com。wosee。masike。common。exception。BaseException业务异常。问题0：为什么要loadclass
　　我们来看触发类加载的org。apache。logging。log4j。core。impl。ThrowableProxy类，
　　这个类有一个注释
　　AproxyisusedtorepresentathrowablethatmaynotexistinadifferentclassloaderorJVM。WhenanapplicationdeserializesaThrowableProxy，thethrowablemaynotbeset，butthethrowablesinformationispreservedinotherfieldsoftheproxylikethemessageandstacktrace。
　　大意就是这个类为了实现异常信息可以跨网络传输，本地的LogEvent可能会传输给另外的JVM，便于不同JVM可以识别这个异常，LogEvent对日志事件做了封装，对异常做了一些扩展，添加了一些扩展信息，比如异常栈所属的jar包、版本等（普通的堆栈里没有打印这些）。
　　ThrowableProxyHelper。toExtendedStackTrace是上述功能的具体实现。主要做了下面这些事情：拿到方法所属的类，从类中获取jar包的位置和版本因为异常栈中没有保存class对象，只有类名，因此需要做类加载。（当然也不是所有的都需要，这里有一个小优化不展开说）
　　这部分简化过的代码逻辑如下：staticExtendedStackTraceElement〔〕toExtendedStackTrace（finalThrowableProxysrc，finalStackClasslt；？stack，finalMapString，CacheEntrymap，finalStackTraceElement〔〕rootTrace，finalStackTraceElement〔〕stackTrace）｛intstackLength；finalExtendedStackTraceElement〔〕extStackTracenewExtendedStackTraceElement〔stackLength〕；Classlt；？clazzstack。isEmpty（）？null：stack。peek（）；ClassLoaderlastLoadernull；遍历堆栈for（intistackLength1；i0；i）｛finalStackTraceElementstackTraceElementstackTrace〔i〕；finalStringclassNamestackTraceElement。getClassName（）；ThestackreturnedfromgetCurrentStackmaybemissingentriesforjava。lang。reflect。Method。invoke（）anditsimplementation。TheThrowablemightalsocontainstackentriesthatarenolongerpresentasthosemethodshavereturned。ExtendedClassInfoextClassInfo；finalCacheEntrycacheEntrymap。get（className）；在缓存列表中直接返回if（cacheEntry！null）｛finalCacheEntryentrycacheEntry；extClassInfoentry。element；if（entry。loader！null）｛lastLoaderentry。loader；｝｝else｛不再则加载类，然后加入缓存列表finalCacheEntryentrytoCacheEntry（ThrowableProxyHelper。loadClass（lastLoader，className），false）；extClassInfoentry。element；map。put（className，entry）；if（entry。loader！null）｛lastLoaderentry。loader；｝｝extStackTrace〔i〕newExtendedStackTraceElement（stackTraceElement，extClassInfo）；｝returnextStackTrace；｝复制代码
　　只有在需要获取额外的异常堆栈信息时，才会触发这里的逻辑，正常的打日志是不会出现的。
　　比如logger。error（e）；logger。error（happenedserviceexception！message：｛｝，e）；复制代码
　　第一种方式的输出是〔2022111508：04：43。316〕〔main〕〔ERROR〕〔com。github。shehanperera。example。MyTest〕java。lang。IllegalArgumentException：Objectvarargsmustnotbenull复制代码
　　这里不需要堆栈信息，不会触发类加载
　　第二种方式的输出java。lang。IllegalArgumentException：Objectvarargsmustnotbenullatorg。apache。commons。lang3。StringUtils。joinWith（StringUtils。java：4880）〔commonslang33。12。0。jar：3。12。0〕atcom。cvte。ya。MyTest。main（MyTest。java：36）〔classes：？〕复制代码
　　这种情况下就会触发类加载获取额外的信息，比如这里的commonslang33。12。0。jar：3。12。0。
　　这里看起来没什么毛病，但是为什么会提示找不到org。apache。rocketmq。client。consumer。listener。MessageListenerOrderly这个接口明明是在业务jar中是存在的。
　　通过上面的调用堆栈可以发现上面的类加载中，最终类的加载被委托到最顶层的BootstrapClassLoader。
　　这里的逻辑就比较清楚了，当初始化类的时候，发现其父类还没有进行过初始化，则需要先触发其父类的初始化。org。apache。rocketmq。。。MessageListenerOrderly这个接口的加载被触发是因为需要加载实现类com。cvte。。。RocketMqListenerOrderlyWrapperCreatorRocketListenerOrderlyWrapper。而且可以推断：com。cvte。。。RocketMqListenerOrderlyWrapperCreatorRocketListenerOrder这个内部类在内存中加载成功了，通过jvm解析这个类的字节码，发现它实现了org。apache。rocketmq。。。MessageListenerOrderly接口，于是去尝试加载这个接口但是失败了。
　　这里就有四个奇怪的问题：为什么RocketMqListenerOrderlyWrapperCreatorRocketListenerOrderlyWrapper是由BootstrapClassLoader去加载的为什么org。apache。rocketmq。。。MessageListenerOrderly接口加载失败了为什么会导致native内存上涨为什么agent的功能还是正常的问题1：为什么由BootstrapClassLoader去加载
　　这就要再看看双亲委派相关的知识，引用《深入理解Java虚拟机》这本书的原话：
　　双亲委派模型的工作过程是：如果一个类加载器收到了类加载的请求，它首先不会自己去尝试加载这个类，而是把这个请求委派给父类加载器去完成，每一个层次的类加载器都是如此，因此所有的加载请求最终都应该传送到最顶层的启动类加载器中，只有当父加载器反馈自己无法完成这个加载请求（它的搜索范围中没有找到所需的类）时，子加载器才会尝试自己去完成加载。
　　JVM中内置了三个重要的ClassLoader，分别是BootstrapClassLoader、ExtensionClassLoader和AppClassLoader
　　这部分源码非常简单，就是一个递归查询。protectedClasslt；？loadClass（Stringname，booleanresolve）throwsClassNotFoundException｛synchronized（getClassLoadingLock（name））｛First，checkiftheclasshasalreadybeenloadedClasslt；？cfindLoadedClass（name）；if（cnull）｛try｛if（parent！null）｛当父类加载器存在时，交给父类去加载cparent。loadClass（name，false）；｝else｛父类加载为空时，交给BootstrapcfindBootstrapClassOrNull（name）；｝｝catch（ClassNotFoundExceptione）｛如果父类加载器们抛出了ClassNotFoundException异常说明父类加载无法完成加载｝if（cnull）｛当父类加载无法加载时再调用本身的findClass来进行类加载cfindClass（name）；｝｝if（resolve）｛resolveClass（c）；｝returnc；｝｝复制代码
　　从上面的堆栈可以看出，加载com。cvte。。。RocketMqListenerOrderlyWrapperCreatorRocketListenerOrderlyWrapper类确实使用了双亲委派，经过好几次父类加载器的加载失败，委托给了Bootstrap。
　　理论上来说javaagent的jar不会出现Bootstrap类加载器的classpath搜索列表里，后面去看了一下javaagent的代码，确实我们为了注入java的内部类（线程池等），agent的jar包需要被Bootstrap类加载器加载，否则Bootstrap类加载器就找不到javaagent中的类了。publicclassAgentMain｛publicstaticvoidpremain（StringagentArguments，Instrumentationinstrumentation）｛try｛finalFileagentJarFilegetAgentJarFile（）；try（JarFilejarFilenewJarFile（agentJarFile））｛将agent的jar包加入到BootstrapClassLoaderinstrumentation。appendToBootstrapClassLoaderSearch（jarFile）；｝｝catch（Exceptione）｛System。err。println（Failedtostartagent）；｝｝｝复制代码
　　到这里就搞清楚了第一个问题，因为agent的jar被加入Bootstrap的classpath路径，又因为双亲委派，导致BootstrapClassLoader加载成功了com。cvte。。。RocketMqListenerOrderlyWrapperCreatorRocketListenerOrderlyWrapper。问题2：为什么org。apache。rocketmq。。。MessageListenerOrderly接口加载失败了
　　众所周知，BootstrapClassLoader是由C实现的，这个类加载器负责加载存放在lib目录，或者被Xbootclasspath参数所指定的路径中存放的jar文件。上面提到在premain中我们把javaagent自己的jar加入到了Bootstrap的classpath，使得javaagent中的com。cvte。。。RocketMqListenerOrderlyWrapperCreatorRocketListenerOrderlyWrapper可以被加载，但是javaagent中不会将rocketmq的jar打包到自己的jar中，而是采用provided的方式，由使用方提供。dependencygroupIdorg。apache。rocketmqgroupIdrocketmqclientartifactIdversion4。7。0versionscopeprovidedscopedependency复制代码
　　也就是说包含了org。apache。rocketmq。。。MessageListenerOrderly接口的rocketmqclient4。7。0。jar这个jar并不会被加入到Bootstrap的classpath中，因此MessageListenerOrderly接口加载失败，因为实现的接口加载失败，导致jvm认为com。cvte。。。RocketMqListenerOrderlyWrapperCreatorRocketListenerOrderlyWrapper加载失败。问题3：为什么native内存会增长
　　看到这里，可能很多人已经大概知道是为什么了，先说结论：
　　BootstrapClassLoader是C实现的，会把RocketListenerOrderlyWrapper文件加载到native内存中，然后进行解析，一般来说，BootstrapClassLoader要加载的类，要么加载成功，要么不存在不需要加载。如果加载成功则会将类写入到一个全局的hashmap中，下次要加载时直接返回，不用重复解析类文件。
　　但是这里的情况有点特殊，RocketListenerOrderlyWrapper类加载失败了，但是加载过程产生的native内存不会被释放。又因为业务一直在抛异常导致RocketListenerOrderlyWrapper类一直尝试被加载，但是没有一次能成功，导致native内存持续上涨。
　　接下来我们用gdb调试的方式来验证上面的过程。
　　首先在ClassLoader：：loadclassfile函数打一个断点，可以看到这里的逻辑是遍历BootstrapClassLoader的classpath尝试加载com。cvte。。。RocketMqListenerOrderlyWrapperCreatorRocketListenerOrderlyWrapper类。
　　跟进ClassPathEntry。openstream方法，因为是一个最终进入到了ClassPathZipEntry：：openstream中，这个方法从jar中读取文件，写入到buffer开始的地址中。
　　通过x命令也可以看到class文件的魔数，确实加载成功了一个class文件。
　　这块内存确实是native内存管理的，我们可以通过地址去pmap中反向查找。
　　我写了一个小工具pmapx，来查某个地址处于什么内存地址段区间中，还可以dump内存到文件，还可以在内存中搜索16进制或者字符串，这个工具后面会释放出来。pmapxtyperangepidpidofjavaaddr0x7f2f98230198grepC100x7f2f98230198复制代码
　　可以看到这块内存是属于典型的Linuxmalloc64M内存区域（59808572865536KB）。
　　到这里，我们可以看到comcvtepsdpragentrocketmqconsumerpushRocketMqListenerConcurrentlyWrapperCreatorRocketListenerConcurrentlyWrapper。class被加载到内存中，接下来就是进行类文件解析了。
　　在ClassFileParser：：parseClassFile上打一个断点。
　　这里的cfs是ClassFileStream类型的指针，ClassFileStream内部包裹了我们上面加载的类文件内存指针buffer。ClassFileStreamcfsstream（）；classClassFileStream：publicResourceObj｛private：u1bufferstart；Bufferbottomu1bufferend；Buffertop（onepastlastelement）u1buffer（）const｛returnbufferstart；｝｝复制代码
　　接下来就是开始解析字节码，判断魔数、版本、常量池等。
　　随后进入到接下接口的环节，这里的接口数量为1，解析到interface的类名以后会尝试去加载。
　　接下来调用SystemDictionary：：resolveinstanceclassornull来尝试加载orgapacherocketmqclientconsumerlistenerMessageListenerConcurrently接口，最后走到了ClassLoader：：loadclassfile来尝试加载orgapacherocketmqclientconsumerlistenerMessageListenerConcurrently。class文件，通过stream值我们可以发现，确实在BootstrapClassLoader中没有找到这个class文件。
　　调用堆栈为
　　至此，native内存增长的原因也比较清楚了，BootstrapClassLoader每次都被触发读取com。cvte。。。RocketMqListenerOrderlyWrapperCreatorRocketListenerOrderlyWrapper。class字节码到内存中，但是因为依赖的接口加载失败，导致整体加载失败，不会被写入到SystemDictionary的全局hashmap，导致每次都要重新加载写入新的native内存。
　　这个过程如下所示。
　　验证想法
　　把log4j的日志级别设置为off就可以来验证这个问题。
　　修改以后继续压测内存占用果然稳如老狗，如下图所示。
　　问题4：为什么预发agent的功能还是正常的
　　这里就要提一下bytebuddy的类加载逻辑，bytebuddy封装了几个常用的ClassLoaderByteArrayClassLoader：bytebuddy自定义类加载器，继承自ClassLoader，未重写loadClass方法，符合双亲委派模式ByteArrayClassLoaderChildFirst：ChildFirst继承了ByteArrayClassLoader，但是重写了loadClass方法，破坏了双亲委派模式。
　　ChildFirst类加载的源码如下：publicstaticclassChildFirstextendsByteArrayClassLoader｛protectedClasslt；？loadClass（Stringname，booleanresolve）throwsClassNotFoundException｛如果已加载直接返回Classlt；？typefindLoadedClass（name）；if（type！null）｛returntype；｝try｛如果没有加载，则先自己尝试查找，打破双亲委派typefindClass（name）；if（resolve）｛resolveClass（type）；｝returntype；｝catch（ClassNotFoundExceptionexception）｛Ifanunknownclassisloaded，thisimplementationcausesthefindClassmethodofthisinstancetobetriggeredtwice。ThisishoweverofminorimportancebecausethiswouldresultinaClassNotFoundExceptionwhatdoesnotaltertheoutcome。自己实在找不到，就交给父类returnsuper。loadClass（name，resolve）；｝｝｝复制代码
　　com。cvte。psd。pr。agent。rocketmq。consumer。push。RocketMqListenerOrderlyWrapperCreatorRocketListenerOrderlyWrapper正是由ByteArrayClassLoaderChildFirst这个classloader加载的。这个可以通过堆内存dump来确认。
　　ByteArrayClassLoaderChildFirst打破了双亲委派，不会先将类委托给BootstrapClassLoader，也就不会出现问题，javaagent功能一切正常。
　　至此，问题分析结束。如何解决修改jvm解决native内存泄露修改log4j去掉ThrowableProxytoExtendedStackTrace没什么用的逻辑