ERROR日志打印导致CPU满载

news/2024/11/15 4:33:40/

描述

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

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

分析

复现

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

image

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的PluginClassLoaderif (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的PluginClassLoaderclazz = 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的PluginClassLoaderreturn 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加载失败的问题。

image

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 classif (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 classif (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: nullat 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 nanoclockif (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火焰图输出如下：

image


http://www.ppmy.cn/news/491553.html

相关文章

用Python实现Linux系统占用指定内存，CPU满载

用Python实现Linux系统占用指定内存，CPU满载

背景 提出两个需求 占满系统CPU占用大内存 通过上网查资料&#xff0c;做实验使用Python实现了上述两个需求。 先看效果 执行前 内存 CPU 执行后 内存 CPU 代码实现 环境说明&#xff1a;代码使用Python3实现 #! /user/bin/env python # -*- encoding: utf-8 -*- import…
阅读更多...
如何模拟FullGC导致CPU满载问题

如何模拟FullGC导致CPU满载问题

系列文章目录 第一章 如何保证多个线程的顺序执行&#xff1f; 第二章 如何排查线上环境内存使用过大&#xff1f; 第三章 如何模拟FullGC导致CPU满载问题&#xff1f; 文章目录 前言排查故障一、构建模拟环境二、Java VisualVM查看在命令行输入&#xff0c;启动VisualVM安装…
阅读更多...
什么软件测试cpu满载,截然相反！CPU满载压力测试

什么软件测试cpu满载,截然相反！CPU满载压力测试

CPU满载压力测试 本项目采用ORTHOS软件使核心达到满载状态，模拟极端使用环境(运行大型游戏、软件时常会出现CPU满载的现象)。 Intel Core i5 2300满载运行6分钟后温度88℃ Intel Core i5 2300满载运行6分钟后CPU倍频会被自动减低至17x，CPU的主频为1.7GHz，相信是Intel的过热保…
阅读更多...
python cpu_python 让cpu满载

python cpu_python 让cpu满载

python 让cpu满载 发布时间&#xff1a;2018-07-29 17:25:11编辑&#xff1a;admin阅读(5939) 搞zabbix监控的时候&#xff0c;linux服务器的负载很低&#xff0c;如何写一个python脚本&#xff0c;让它满载呢&#xff1f; 网上搜了一堆&#xff0c;发现各种不靠谱。后来终于发…
阅读更多...
电脑cpu莫名占用满的解决方法有哪些呢？

电脑cpu莫名占用满的解决方法有哪些呢？

cpu占用率高导致电脑卡的头疼。win10电脑CPU占用率高的原因很多&#xff0c;可能是某个程序占用率大&#xff0c;或者是某个系统服务所致&#xff0c;又或者是系统BUG导致。 更多重装系统教程尽在小白系统重装官网 ​ 方法一、结束进程 1、同时按下Ctrl、Alt和Del键。弹出操作…
阅读更多...
数据库CPU满载如何处理

数据库CPU满载如何处理

当数据库CPU满载时&#xff0c;我们首先要做的是让CPU降下来&#xff0c;优先保证系统的可用性。 什么情况会导致数据库CPU飙升呢&#xff1f; QPS过高&#xff1a; 高并发&#xff0c;也就是数据库承载的流量过大。慢SQL&#xff1a; 少量或大量慢SQL占用CPU资源&#xff0c…
阅读更多...
Python数据类型转换函数大全

Python数据类型转换函数大全

虽然 Python 是弱类型编程语言&#xff0c;不需要像 Java 或 C 语言那样还要在使用变量前声明变量的类型&#xff0c;但在一些特定场景中&#xff0c;仍然需要用到类型转换。 比如说&#xff0c;我们想通过使用 print() 函数输出信息“您的身高&#xff1a;”以及浮点类型 hei…
阅读更多...
microsoft已过期

microsoft已过期

microsoft已过期 第一步&#xff1a;点击红色剪头&#xff0c;选择设置 第二步&#xff1a;点击&#xff1a;关于microsoft edge&#xff1b;等待更新&#xff0c;重启就行。
阅读更多...
最新文章

Copyright @ 2022~2023