ERROR日志打印导致CPU满载

描述

开发环境对一台测试节点进行压测时，由于参数配置错误导致请求没有业务处理直接报错。随即停止压测后登录测试机器排查日志，以外发现虽然已经没有请求到该节点，但应用依然在打印错误日志，并且看日志时间是在打印几分钟前请求的日志。

第一反应是异步打印的日志出现堆积，于是查看了该应用所在节点的物理资源，发现CPU已经满荷载，以及JVM触发了多次Full GC和OOM。

分析

复现

该节点重启后，以50TPS的速率故意发起错误请求的压测，果然稳定复现CPU满载的问题，因此盲猜是因为CPU满载导致异步日志打印速率慢，生产速度高于消费速度而出现日志堆积的情况，最终内存耗尽触发Full GC和OOM。通过arthas打印CPU火焰图后，发现CPU资源的消耗主要分布在日志异步打印时Class类加载方面，火焰图如下：

CPU满载原因

到这里有点摸不到头脑，大量日志打印会消耗CPU资源能理解，但仅仅每秒50次的日志打印也能吃满CPU？以及为什么日志打印会在类加载上消耗如此多的CPU资源？火焰图中为什么会出现3个类加载执行步骤？为了清楚以上问题，通过远程Debug来翻看该场景下日志打印的源代码实现。

通过层层debug，发现问题的核心代码逻辑在org.apache.logging.log4j.core.impl.ThrowableProxy#loadClass(java.lang.ClassLoader, java.lang.String)这个方法中。但打印ERROR日志的异常堆栈时，会尝试加载该异常堆栈中所有的类，类加载的代码实现如下。例如一个异常堆栈有76层，则会对这76个异常堆栈的类进行类加载，但事实上由于应用是SofaArk应用，存在多个破坏双亲委任的类加载器，导致此处逻辑虽然最多会尝试3次类加载，但始终都是使用SofaArk的PluginClassLoader对Class类进行尝试加载。

因此如果异常堆栈中出现PluginClassLoader加载不到的类，就会出现CPU火焰图中类加载3次的情况。

private Class<?> loadClass(final ClassLoader lastLoader, final String className) {
    Class<?> clazz;
    // lastLoader为异常堆栈中上一个成功加载的Class类的类加载器
    // 始终为SofaArk的PluginClassLoader
    if (lastLoader != null) {
        try {
            clazz = lastLoader.loadClass(className);
            if (clazz != null) {
                return clazz;
            }
        } catch (final Throwable ignore) {
            // Ignore exception.
        }
    }
    try {
        // 实际使用Class.forName(className)
        // 通过LoaderUtil的classloader加载类,始终为SofaArk的PluginClassLoader
        clazz = LoaderUtil.loadClass(className);
    } catch (final ClassNotFoundException | NoClassDefFoundError e) {
        return loadClass(className);
    } catch (final SecurityException e) {
        return null;
    }
    return clazz;
}

private Class<?> loadClass(final String className) {
    try {
        // 使用ThrowableProxy的classloader加载类,始终为SofaArk的PluginClassLoader
        return Loader.loadClass(className, this.getClass().getClassLoader());
    } catch (final ClassNotFoundException | NoClassDefFoundError | SecurityException e) {
        return null;
    }
}

那么问题来了，为什么三次类加载都是用的PluginClassLoader尝试加载Class类？有哪些类是PluginClassLoader类加载器加载不到的？这里就涉及到SofaArk的类加载机制了，SofaArk中有两种类加载器：PluginClassLoader和BizClassLoader，前者加载不到Ark业务的类，后者加载不到Ark插件的类。

而SofaArk为了提供模块瘦身的能力，提前将大量的常用依赖jar包已经加载到SofaArk中，开发者就不需要再将这些依赖包再打包到运行jar包中，从而显著降低了运行包的体积。但这个功能导致了另外的一个问题：这些依赖jar包会优先由PluginClassLoader加载。其中就包括了log4j相关依赖，因此log4j的类加载器是PluginClassLoader，所以上述三次类加载过程中，始终都是通过PluginClassLoader尝试加载Class类。最终导致当一个异常堆栈打印时，其中的业务代码的类和其他未被SofaArk管控依赖的类会出现PluginClassLoader加载失败的问题。

protected Class<?> loadClassInternal(String name, boolean resolve) throws ArkLoaderException {
    Class<?> clazz = null;

    // 0. sun reflect related class throw exception directly
  	// 如果是加载反射生成的字节码,直接抛出ClassNotFoundException,终止类加载
    if (classloaderService.isSunReflectClass(name)) {
        throw new ArkLoaderException(
            String
                .format(
                    "[ArkPlugin Loader] %s : can not load class: %s, this class can only be loaded by sun.reflect.DelegatingClassLoader",
                    pluginName, name));
    }

    // 1. findLoadedClass
    // 查找已经被加载过的类
    if (clazz == null) {
        clazz = findLoadedClass(name);
    }

    // 2. JDK related class
    // 查找JDK中的类:ExtClassloader负责加载的类和SystemClassloader的classpath中的类
    if (clazz == null) {
        clazz = resolveJDKClass(name);
    }

    // 3. Ark Spi class
    // SofaArk自身提供的接口类
    if (clazz == null) {
        clazz = resolveArkClass(name);
    }

    // 4. pre find class
    if (clazz == null) {
        clazz = preLoadClass(name);
    }

    // 5. Import class export by other plugins
    // 看是否在插件的import中,如果在则会委托给导出该类的插件类加载器加载
    if (clazz == null) {
        clazz = resolveExportClass(name);
    }

    // 6. Plugin classpath class
    // 在插件自身的classpath中加载,此处CPU资源消耗严重
    if (clazz == null) {
        clazz = resolveLocalClass(name);
    }

    // 7. Java Agent ClassLoader for agent problem
    // 查找Java Agent中的类
    if (clazz == null) {
        clazz = resolveJavaAgentClass(name);
    }

    // 8. Post find class
    if (clazz == null) {
        clazz = postLoadClass(name);
    }

    if (clazz != null) {
        if (resolve) {
            super.resolveClass(clazz);
        }
        return clazz;
    }

    throw new ArkLoaderException(String.format(
        "[ArkPlugin Loader] %s : can not load class: %s", pluginName, name));
}

继续翻找日志打印源码发现，log4j之所以对异常堆栈中每一个类尝试类加载，实际上是为了获取该类所在的jar包名称和版本号，用于日志打印。而对于类加载失败时，则jar包名称和版本号均以?表示，最终输出的异常堆栈日志格式如下：

java.lang.RuntimeException: null
	at com.wakzz.service.ContentManageFacadeImpl.queryByIds(ContentManageFacadeImpl.java:105) ~[?:?]
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ~[spring-core-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:750) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
	at com.alicp.jetcache.anno.aop.JetCacheInterceptor.invoke(JetCacheInterceptor.java:42) ~[?:?]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
	at com.alicp.jetcache.anno.aop.JetCacheInterceptor.invoke(JetCacheInterceptor.java:42) ~[?:?]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
	at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:88) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
	at sun.reflect.GeneratedMethodAccessor180.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_232]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_232]
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:644) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:633) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
	at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
	at sun.reflect.GeneratedMethodAccessor179.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_232]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_232]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_232]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_232]
	at java.lang.Thread.run(Thread.java:858) [?:1.8.0_232]

通过jar包名称和版本号均为?判断该类为3次类加载失败的情况，如果异常堆栈中有13个类加载失败，该场景下一次异常堆栈打印需要执行39次类加载过程。因此复现步骤中虽然是以50TPS的低频率进行请求，但实际上导致了每秒近2000次的类加载。而复现步骤中抛出异常的位置是业务代码入口，因此涉及到的Ark业务类较少，试想一下，如果异常从比较深的路径上抛，一次请求中多次打印的异常堆栈，那么甚至可能出现每秒十几次甚至几次的持续错误请求就足够将该应用的CPU打垮而发生线上事故。

解决

通过分析得知，异常堆栈打印之所以导致CPU满载，是因为SofaArk应用多个ClassLoader实现的类隔离和瘦身能力导致异常堆栈日志打印时频繁执行无效的类加载过程，而通过CPU火焰图发现PluginClassLoader的resolveLocalClass方法对CPU资源消耗严重。

分析出问题引起的导火索是日志打印异常堆栈时输出jar包名称和版本号，因此盲猜涉及到了日志的输出格式。应用中使用的还是log4j作为日志输出工具，因此翻找log4j的日志格式文档。文档中详细记录了异常堆栈的三种输出格式：

1. ex|exception|throwable: 输出完整的异常堆栈，输出格式和Throwable.printStackTrace()相同
2. rEx|rException|rThrowable: 异常堆栈从第一个引发的异常开始打印(实测也打印类所在目录的jar包名称)
3. xEx|xException|xThrowable: 除了输出ex|exception|throwable的信息外，还输出类所在的包信息，例如类所在目录的jar包名称

然后查看应用的日志输出配置，发现部分日志的输出格式没有表明异常堆栈的输出格式，如下：

<PatternLayout pattern="%d %-5p %c{2} - %m%n" charset="UTF-8"/>

通过log4j源码org.apache.logging.log4j.core.pattern.PatternParser#parse(java.lang.String, boolean, boolean, boolean)可得，异常堆栈的默认输出格式为xEx|xException|xThrowable。即未配置异常输出格式时，默认会通过类加载获取异常堆栈中每个类的包名和版本号。

for (final PatternConverter converter : converters) {
    if (converter instanceof NanoTimePatternConverter) {
        // LOG4J2-1074 Switch to actual clock if nanosecond timestamps are required in config.
        // LOG4J2-1248 set config nanoclock
        if (config != null) {
            config.setNanoClock(new SystemNanoClock());
        }
    }
    LogEventPatternConverter pc;
    if (converter instanceof LogEventPatternConverter) {
        pc = (LogEventPatternConverter) converter;
        handlesThrowable |= pc.handlesThrowable();
    } else {
        pc = new LiteralPatternConverter(config, Strings.EMPTY, true);
    }

    FormattingInfo field;
    if (fieldIter.hasNext()) {
        field = fieldIter.next();
    } else {
        field = FormattingInfo.getDefault();
    }
    list.add(new PatternFormatter(pc, field));
}
// 当未配置异常输出格式时,默认使用ExtendedThrowablePatternConverter(xEx|xException|xThrowable格式)
if (alwaysWriteExceptions && !handlesThrowable) {
    final LogEventPatternConverter pc = ExtendedThrowablePatternConverter.newInstance(config, null);
    list.add(new PatternFormatter(pc, FormattingInfo.getDefault()));
}

因此解决方案就很简单了，修改log4j的日志配置，强制指定每个日志文件的异常堆栈格式为ex|exception|throwable，修改如下：

<!-- 修改前 -->
<PatternLayout pattern="%d %-5p %c{2} - %m%n" charset="UTF-8"/>

<!-- 修改后 -->
<PatternLayout pattern="%d %-5p %c{2} - %m%n%throwable" charset="UTF-8"/>

修改后，再对应用以50TPS的频率进行压测，CPU资源满载的问题已经解决，其CPU火焰图输出如下：