ERROR日志打印导致CPU满载

祈雨的笔记

安全多方计算MPC spark原理解析 kueue执行源码分析 spark on k8s执行源码分析 spark-operator源码解析系统压测遇到的缓存击穿问题我的世界PC与安卓联机蚂蚁金服流量投放平台的AIG改造 G1大对象致Old区占用率高日志打印导致接口响应率下跌分析 Groovy加载类导致OOM分析记OceanBase死锁超时应用发版期间服务响应超时 Ark Serverless初探系统优化复盘一二三 The user specified as a definer does not exist Kong网关初探 API网关选型调研 CPU火焰图常用工具配置中心选型调研 root操作Nginx导致用户组错误基于Proxifier使用代理 FastJSON字段智能匹配踩坑 Nacos初探记一次Nginx服务器CPU满荷载故障基于券系统分库分表的思考 limit不参与SQL成本计算致索引失效 Linux常用性能监控命令 golang低版本http2偶现400 hostname in certificate didn't match

ERROR日志打印导致CPU满载

祈雨的笔记 · 2021-09-04 · via 祈雨的笔记

描述

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

第一反应是异步打印的日志出现堆积，于是查看了该应用所在节点的物理资源，发现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;
    
    
    if (lastLoader != null) {
        try {
            clazz = lastLoader.loadClass(className);
            if (clazz != null) {
                return clazz;
            }
        } catch (final Throwable ignore) {
            
        }
    }
    try {
        
        
        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 {
        
        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;

    
  	
    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));
    }

    
    
    if (clazz == null) {
        clazz = findLoadedClass(name);
    }

    
    
    if (clazz == null) {
        clazz = resolveJDKClass(name);
    }

    
    
    if (clazz == null) {
        clazz = resolveArkClass(name);
    }

    
    if (clazz == null) {
        clazz = preLoadClass(name);
    }

    
    
    if (clazz == null) {
        clazz = resolveExportClass(name);
    }

    
    
    if (clazz == null) {
        clazz = resolveLocalClass(name);
    }

    
    
    if (clazz == null) {
        clazz = resolveJavaAgentClass(name);
    }

    
    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的日志格式文档。文档中详细记录了异常堆栈的三种输出格式：

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

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

1	<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) {
        
        
        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));
}

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火焰图输出如下：

此内容由惯性聚合(RSS阅读器)自动聚合整理，仅供阅读参考。原文来自 — 版权归原作者所有。

推荐订阅源

祈雨的笔记

描述

分析

复现

CPU满载原因

解决