作 者 | 张彬彬
01 背景
ChaosBlade 是阿里巴巴开源的一款遵循混沌工程原理和混沌实验模型的实验注入工具，帮助企业提升分布式系统的容错能力，并且在企业上云或往云原生系统迁移过程中业务连续性保障。
目前支持的场景有：基础资源、Java 应用、C++ 应用、Docker 容器以及 Kubernetes 平台。该项目将场景按领域实现封装成单独的项目，不仅可以使领域内场景标准化实现，而且非常方便场景水平和垂直扩展，通过遵循混沌实验模型，实现 ChaosBlade cli 统一调用。
不过 Java 场景下的故障注入目前有一些性能问题,主要体现在故障注入时会让 CPU 的使用率大幅度抖动,严重情况下可能会导致 CPU 的使用率 100%。这种情况对于线下服务的影响还好，但是对于线上服务就比较严重了，因为 CPU 的使用率较高有可能会导致服务的整体性能变差，从而影响接口的耗时。
通过对 ChaosBlade Java 场景的性能优化，使 CPU 在故障注入时的抖动得到了有效的控制，不会再出现 CPU 使用率达到 100% 的抖动，经过测试在线上 8C，4G，QPS 3K 左右的服务实例上注入 Dubbo 自定义抛异常的故障，CPU 的使用率可以控制在 40% 左右的瞬时抖动范围内,性能整体提升近 2.5 倍。
本文将会详细的介绍影响性能的问题点以及是如何对这些问题进行优化的。
02 Java 场景
在介绍前先了解下 ChaosBlade Java 场景的注入流程。
Java 场景的故障注入是基于字节码增强框架 JVM-Sandbox 实现的，注入一个故障分为两步：
1.ChaosBlade 执行 prepare 命令，触发 sandbox 对目标 JVM 挂载 Java agent。
2.ChaosBlade 执行 create 命令，触发 sandbox 对目标 JVM 进行字节码增强，从而达到故障注入的目的。
03 Prepare（挂载）阶段优化
1 现象
本地模拟一个简单的 HTTP 服务，控制其 CPU Idle 在 50% 左右，当执行 blade prepare jvm --pid 挂载 agent 后，发现 CPU 空闲率迅速下降，并且下降的幅度较大。在生产中进行故障注入有可能会直接让 Idle 掉低从而触发告警：
2 定位
通过采集 CPU profile 生成火焰图来观察在执行 blade prepare 时 CPU 的使用情况，如下图可以看到 loadPlugins 方法是资源消耗的重灾区。
loadPlugins方法中主要是加载 ChaosBlade Java 中支持的全部插件，例如 dubbo,redis,kafka 等。当加载了这些插件后就可以进行故障注入了。加载插件的过程中会对插件中定义的类以及方法进行字节码增强。
导致 CPU 消耗的问题就在于加载全量的插件耗时较大，而我们故障注入时会选择具体某个插件进行故障注入，显然全量加载并不是最优解
3 优化
优化思路：既然故障注入时会选择具体的插件，那么通过懒加载的方式即可解决，当我们要针对哪一个插件故障注入就加载哪个插件，加载的粒度变小，CPU 的消耗自然就小了：
核心代码：
在故障注入阶段，通过指定的插件进行懒加载。
private void lazyLoadPlugin(ModelSpec modelSpec, Model model) throws ExperimentException {
PluginLifecycleListener listener = ManagerFactory.getListenerManager().getPluginLifecycleListener();
if (listener == null) {
throw new ExperimentException("can get plugin listener");
}
PluginBeans pluginBeans = ManagerFactory.getPluginManager().getPlugins(modelSpec.getTarget());
if (pluginBeans == null) {
throw new ExperimentException("can get plugin bean");
}
if (pluginBeans.isLoad()) {
return;
}
listener.add(pluginBean);
ManagerFactory.getPluginManager().setLoad(pluginBeans, modelSpec.getTarget());
}
详细代码 PR：
https://github.com/ChaosBlade-io/ChaosBlade-exec-jvm/pull/233
4 改进后效果
CPU Idle 下降幅度降低
火焰图中的 CPU 使用率几乎“消失”
04 Create（注入）阶段优化
在实际使用中发现故障注入导致 CPU Idle 跌底的情况比较多，跌底的持续时间是比较短暂的基本都在 20S 左右，有一些情况是和目标服务的业务代码有关系或者是和目标服务的 jvm 参数设置有关，本文只介绍由 ChaosBlade 导致的或间接导致的 CPU Idle 跌底问题。
CPU Idle 跌底：这里指的是 CPU 空闲率降低为 0，同时意味着 CPU 使用率达到了 100%。
1 Dubbo 故障优化
问题描述
ChaosBlade 中支持对 dubbo provider 或者 consumer 进行故障注入（例如抛异常），当一个服务既是 provider 又是 consumer 的时候，如果对 provider 故障注入则会触发 bug，有可能会导致 CPU Idle 跌底。
正常情况：一个既是 provider 又是 consumer 的服务，它的请求处理流程是流量会首先进入到 provider 经过处理后交由业务逻辑执行，最后通过 consumer 将请求转发出去。
针对 consumer 故障注入：当利用 ChaosBlade 对 consumer 进行故障注入时，流量到达 consumer 就会抛出异常，不会将流量真正的转发出去，从而达到一个模拟故障发生的效果。
针对 provider 故障注入：当利用 ChaosBlade 对 provider 进行故障注入时，流量到达 provider 就会抛出异常，不会将流量向下转发。
上面说的都是预期效果，实际上 ChaosBlade 无论是对 provider 或者 consumer 进行故障注入时，都会同时 provider 以及 consumer 同时进行故障注入，这就有可能造成额外的资源浪费。
1. 字节码增强的类变的多了
2. 例如当注入 provider 故障时，我们希望流量不要经过业务逻辑，因为一旦是在 consumer 也抛出了异常，流量返回时自然要经过业务逻辑的异常处理（例如打印 error 日志，重试等），这就有可能因为业务逻辑的处理问题导致 CPU Idle 下降。
问题原因：因为 ChaosBlade 的字节码增强逻辑是按照插件的粒度进行的，例如 dubbo 就属于一个插件，不过像 dubbo 和 kafka 这种既有针对 provider 又有针对 consumer 故障注入的插件就会同时对 provider 和 consumer 都注入故障了。
优化
在加载插件的时候，根据具体加载的插件名按需加载，例如执行命令：
./blade create dubbo throwCustomException --provider --exception Java.lang.Exception --service org.apache.dubbo.UserProvider --methodname GetUser
代表实际要针对 dubbo 的 provider 注入故障，那么就只加载 provider 插件进行字节码增强。
修改的核心代码：
private void lazyLoadPlugin(ModelSpec modelSpec, Model model) throws ExperimentException {
// ...... 省略
for (PluginBean pluginBean : pluginBeans.getPluginBeans()) {
String flag = model.getMatcher().get(pluginBean.getName());
if ("true".equalsIgnoreCase(flag)) {
listener.add(pluginBean);
break;
}
listener.add(pluginBean);
}
// ...... 省略
}
}
相关 PR：
https://github.com/ChaosBlade-io/ChaosBlade-exec-jvm/pull/267
2 自定义脚本故障优化
-
问题描述
./blade c jvm script --classname com.example.xxx.HelloController --methodname Hello --script-content .....
问题排查
Stack Trace is:
Java.lang.Thread.State: RUNNABLE
at Java.util.zip.ZipFile.getEntryTime(Native Method)
at Java.util.zip.ZipFile.getZipEntry(ZipFile.Java:586)
at Java.util.zip.ZipFile.access$900(ZipFile.Java:60)
at Java.util.zip.ZipFile$ZipEntryIterator.next(ZipFile.Java:539)
- locked <0x00000006c0a57670> (a sun.net.www.protocol.jar.URLJarFile)
at Java.util.zip.ZipFile$ZipEntryIterator.nextElement(ZipFile.Java:514)
at Java.util.zip.ZipFile$ZipEntryIterator.nextElement(ZipFile.Java:495)
at Java.util.jar.JarFile$JarEntryIterator.next(JarFile.Java:258)
at Java.util.jar.JarFile$JarEntryIterator.nextElement(JarFile.Java:267)
at Java.util.jar.JarFile$JarEntryIterator.nextElement(JarFile.Java:248)
at com.alibaba.ChaosBlade.exec.plugin.jvm.script.Java.JavaCodeScriptEngine$InMemoryJavaFileManager.processJar(JavaCodeScriptEngine.Java:421)
at com.alibaba.ChaosBlade.exec.plugin.jvm.script.Java.JavaCodeScriptEngine$InMemoryJavaFileManager.listUnder(JavaCodeScriptEngine.Java:401)
at com.alibaba.ChaosBlade.exec.plugin.jvm.script.Java.JavaCodeScriptEngine$InMemoryJavaFileManager.find(JavaCodeScriptEngine.Java:390)
at com.alibaba.ChaosBlade.exec.plugin.jvm.script.Java.JavaCodeScriptEngine$InMemoryJavaFileManager.list(JavaCodeScriptEngine.Java:375)
at com.sun.tools.Javac.api.ClientCodeWrapper$WrappedJavaFileManager.list(ClientCodeWrapper.Java:231)
at com.sun.tools.Javac.jvm.ClassReader.fillIn(ClassReader.Java:2796)
at com.sun.tools.Javac.jvm.ClassReader.complete(ClassReader.Java:2446)
at com.sun.tools.Javac.jvm.ClassReader.access$000(ClassReader.Java:76)
at com.sun.tools.Javac.jvm.ClassReader$1.complete(ClassReader.Java:240)
at com.sun.tools.Javac.code.Symbol.complete(Symbol.Java:574)
at com.sun.tools.Javac.comp.MemberEnter.visitTopLevel(MemberEnter.Java:507)
at com.sun.tools.Javac.tree.JCTree$JCCompilationUnit.accept(JCTree.Java:518)
at com.sun.tools.Javac.comp.MemberEnter.memberEnter(MemberEnter.Java:437)
at com.sun.tools.Javac.comp.MemberEnter.complete(MemberEnter.Java:1038)
at com.sun.tools.Javac.code.Symbol.complete(Symbol.Java:574)
at com.sun.tools.Javac.code.Symbol$ClassSymbol.complete(Symbol.Java:1037)
at com.sun.tools.Javac.comp.Enter.complete(Enter.Java:493)
at com.sun.tools.Javac.comp.Enter.main(Enter.Java:471)
at com.sun.tools.Javac.main.JavaCompiler.enterTrees(JavaCompiler.Java:982)
at com.sun.tools.Javac.main.JavaCompiler.compile(JavaCompiler.Java:857)
at com.sun.tools.Javac.main.Main.compile(Main.Java:523)
at com.sun.tools.Javac.api.JavacTaskImpl.doCall(JavacTaskImpl.Java:129)
at com.sun.tools.Javac.api.JavacTaskImpl.call(JavacTaskImpl.Java:138)
at com.alibaba.ChaosBlade.exec.plugin.jvm.script.Java.JavaCodeScriptEngine.compileClass(JavaCodeScriptEngine.Java:149)
at com.alibaba.ChaosBlade.exec.plugin.jvm.script.Java.JavaCodeScriptEngine.compile(JavaCodeScriptEngine.Java:113)
at com.alibaba.ChaosBlade.exec.plugin.jvm.script.base.AbstractScriptEngineService.doCompile(AbstractScriptEngineService.Java:82)
at com.alibaba.ChaosBlade.exec.plugin.jvm.script.base.AbstractScriptEngineService.compile(AbstractScriptEngineService.Java:69)
at com.alibaba.ChaosBlade.exec.plugin.jvm.script.model.DynamicScriptExecutor.run(DynamicScriptExecutor.Java:74)
at com.alibaba.ChaosBlade.exec.common.injection.Injector.inject(Injector.Java:73)
at com.alibaba.ChaosBlade.exec.common.aop.AfterEnhancer.afterAdvice(AfterEnhancer.Java:46)
at com.alibaba.ChaosBlade.exec.common.plugin.MethodEnhancer.afterAdvice(MethodEnhancer.Java:47)
at com.alibaba.ChaosBlade.exec.bootstrap.jvmsandbox.AfterEventListener.onEvent(AfterEventListener.Java:93)
at com.alibaba.jvm.sandbox.core.enhance.weaver.EventListenerHandler.handleEvent(EventListenerHandler.Java:116)
at com.alibaba.jvm.sandbox.core.enhance.weaver.EventListenerHandler.handleOnEnd(EventListenerHandler.Java:426)
at com.alibaba.jvm.sandbox.core.enhance.weaver.EventListenerHandler.handleOnReturn(EventListenerHandler.Java:363)
优化
public interface PreActionExecutor {
/**
* Pre run executor
*
* @param enhancerModel
* @throws Exception
*/
void preRun(EnhancerModel enhancerModel) throws ExperimentException;
}
private void applyPreActionExecutorHandler(ModelSpec modelSpec, Model model)
throws ExperimentException {
ActionExecutor actionExecutor = modelSpec.getActionSpec(model.getActionName()).getActionExecutor();
if (actionExecutor instanceof PreActionExecutor) {
EnhancerModel enhancerModel = new EnhancerModel(EnhancerModel.class.getClassLoader(), model.getMatcher());
enhancerModel.merge(model);
((PreActionExecutor) actionExecutor).preRun(enhancerModel);
}
}
相关 PR： https://github.com/ChaosBlade-io/ChaosBlade-exec-jvm/pull/269
问题描述
- locked <0x00000006f08422d0> (a org.apache.log4j.DailyRollingFileAppender)
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.Java:66)
at org.apache.log4j.Category.callAppenders(Category.Java:206)
- locked <0x00000006f086daf8> (a org.apache.log4j.Logger)
at org.apache.log4j.Category.forcedLog(Category.Java:391)
at org.apache.log4j.Category.log(Category.Java:856)
at org.slf4j.impl.Log4jLoggerAdapter.log(Log4jLoggerAdapter.Java:601)
LOGGER.info("Match rule: {}", JsonUtil.writer().writeValueAsString(model));
Java.lang.Thread.State: RUNNABLE
at Java.lang.String.charAt(String.Java:657)
at Java.io.UnixFileSystem.normalize(UnixFileSystem.Java:87)
at Java.io.File.<init>(File.Java:279)
at sun.net.www.protocol.file.Handler.openConnection(Handler.Java:80)
- locked <0x00000000c01f2740> (a sun.net.www.protocol.file.Handler)
at sun.net.www.protocol.file.Handler.openConnection(Handler.Java:72)
- locked <0x00000000c01f2740> (a sun.net.www.protocol.file.Handler)
at Java.net.URL.openConnection(URL.Java:979)
at sun.net.www.protocol.jar.JarFileFactory.getConnection(JarFileFactory.Java:65)
at sun.net.www.protocol.jar.JarFileFactory.getPermission(JarFileFactory.Java:154)
at sun.net.www.protocol.jar.JarFileFactory.getCachedJarFile(JarFileFactory.Java:126)
at sun.net.www.protocol.jar.JarFileFactory.get(JarFileFactory.Java:81)
- locked <0x00000000c00171f0> (a sun.net.www.protocol.jar.JarFileFactory)
at sun.net.www.protocol.jar.JarURLConnection.connect(JarURLConnection.Java:122)
at sun.net.www.protocol.jar.JarURLConnection.getInputStream(JarURLConnection.Java:152)
at Java.net.URL.openStream(URL.Java:1045)
at Java.lang.ClassLoader.getResourceAsStream(ClassLoader.Java:1309)
......
at Java.lang.reflect.Method.invoke(Method.Java:498)
at com.fasterxml.jackson.databind.ser.BeanPropertyWriter.serializeAsField(BeanPropertyWriter.Java:689)
at com.fasterxml.jackson.databind.ser.std.BeanSerializerBase.serializeFields(BeanSerializerBase.Java:755)
at com.fasterxml.jackson.databind.ser.BeanSerializer.serialize(BeanSerializer.Java:178)
at com.fasterxml.jackson.databind.ser.BeanPropertyWriter.serializeAsField(BeanPropertyWriter.Java:728)
at com.fasterxml.jackson.databind.ser.std.BeanSerializerBase.serializeFields(BeanSerializerBase.Java:755)
at com.fasterxml.jackson.databind.ser.BeanSerializer.serialize(BeanSerializer.Java:178)
at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider._serialize(DefaultSerializerProvider.Java:480)
at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider.serializeValue(DefaultSerializerProvider.Java:319)
at com.fasterxml.jackson.databind.ObjectWriter$Prefetch.serialize(ObjectWriter.Java:1516)
at com.fasterxml.jackson.databind.ObjectWriter._writeValueAndClose(ObjectWriter.Java:1217)
at com.fasterxml.jackson.databind.ObjectWriter.writeValueAsString(ObjectWriter.Java:1086)
at com.alibaba.ChaosBlade.exec.common.injection.Injector.inject(Injector.Java:69)
at com.alibaba.ChaosBlade.exec.common.aop.AfterEnhancer.afterAdvice(AfterEnhancer.Java:46)
at com.alibaba.ChaosBlade.exec.common.plugin.MethodEnhancer.afterAdvice(MethodEnhancer.Java:47)
at com.alibaba.ChaosBlade.exec.bootstrap.jvmsandbox.AfterEventListener.onEvent(AfterEventListener.Java:93)
at com.alibaba.jvm.sandbox.core.enhance.weaver.EventListenerHandler.handleEvent(EventListenerHandler.Java:116)
at com.alibaba.jvm.sandbox.core.enhance.weaver.EventListenerHandler.handleOnEnd(EventListenerHandler.Java:426)
at com.alibaba.jvm.sandbox.core.enhance.weaver.EventListenerHandler.handleOnReturn(EventListenerHandler.Java:363)
at Java.com.alibaba.jvm.sandbox.spy.Spy.spyMethodOnReturn(Spy.Java:192)
优化
LOGGER.info("Match rule: {}", model);
@Override
public String toString() {
return "Model{" +
"target='" + target + '\'' +
", matchers=" + matcher.getMatchers().toString() +
", action=" + action.getName() +
'}';
}
相关 PR： https://github.com/ChaosBlade-io/ChaosBlade-exec-jvm/pull/260
Metaspace is a native (as in: off-heap) memory manager in the hotspot.
It is used to manage memory for class metadata. Class metadata are allocated when classes are loaded.
Their lifetime is usually scoped to that of the loading classloader - when a loader gets collected, all class metadata it accumulated are released in bulk.
-
日志表现
-
本地复现
How to Close a URLClassLoader?
The URLClassLoader close() method effectively eliminates the problem of how to support updated implementations of the classes and resources loaded from a particular codebase, and in particular from JAR files. In principle, once the application clears all references to a loader object, the garbage collector and finalization mechanisms will eventually ensure that all resources (such as the JarFile objects) are released and closed.
-
猜想
-
验证猜想
内部类的引用： EventProcesser$Process SandboxProtector
优化
优化后的相关pr： https://github.com/ChaosBlade-io/jvm-sandbox/pull/1
改进后效果
再次优化
关于 Metaspace 的内存分配以及回收的相关内容可以参考文章： https://www.javadoop.com/post/metaspace
public static void agentmain(String featureString, Instrumentation inst) {
System.gc();
LAUNCH_MODE = LAUNCH_MODE_ATTACH;
final Map<String, String> featureMap = toFeatureMap(featureString);
writeAttachResult(
getNamespace(featureMap),
getToken(featureMap),
install(featureMap, inst)
);
}
相关 PR： https://github.com/ChaosBlade-io/jvm-sandbox/pull/6
自动生成： sun.reflect.DelegatingClassLoader
思考
问题描述
关于即时编译的内容可以参考文章： https://xie.infoq.cn/article/dacbe19251f8ec828efacdfde