日志打印导致接口响应率下跌分析

背景

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

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

最近同事遇到类似的问题,虽然现象有所区别,他们系统的现象是CPU使用率始终在24%,业务接口响应耗时变长,但本质上和我原先在开发环境遇到的问题一直,都是异步打印日志堆积导致的问题。

复现

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

image

分析

类加载器

我们复现的应用是SofaArk应用,SofaArk设计了多个类加载器,因此这里首先要聊一聊SofaArk的类加载机制:SofaArk中有两种类加载器:PluginClassLoader和BizClassLoader。SofaArk为了提供模块瘦身的能力,提前将大量的常用依赖jar包已经加载到SofaArk中,开发者就不需要再将这些依赖包再打包到运行jar包中,从而显著降低了运行包的体积。

image

当前设计PluginClassLoader除了会加载SofaArk相关的类,还会加载plugin管控的依赖的类,但不会加载也无法加载业务代码的类和非plugin管控的类。而BizClassLoader则加载以下类:

  1. 业务代码的类
  2. 业务代码中引用的非plugin管控的依赖的类
  3. 业务代码中通过配置排除plugin管控的类

日志打印流程

通过火焰图可见日志打印消耗了绝大多数CPU资源,因此同样需要理解日志打印的流程。当业务代码中打印异常栈时,就会触发如下的流程。由于log4j的包是通过plugin管控的依赖,因此log4j的类加载器并不是BizClassLoader而是PluginClassLoader。由于项目配置了日志格式为异常栈需要打印jar包名称和版本号,因此当log4j打印异常栈时会通过log4j的类加载器即PluginClassLoader尝试加载每行异常栈的类,用于获取其所在的jar包名称和版本号。

image

但由于SofaArk的类加载器的实现,PluginClassLoader只会加载plugin管控的依赖的类,因此如下以内容平台的一次异常栈举例,业务代码的异常栈(包路径为com.wakzz.service.*)和引入的未被plugin管控的依赖永远尝试加载失败。因此异常栈通过PluginClassLoader尝试获取其所在jar时,始终是先查询已加载类失败,再尝试加载类失败。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
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]

更糟糕的是log4j会对加载失败的类尝试3次,核心代码见org.apache.logging.log4j.core.impl.ThrowableProxy#loadClass(java.lang.ClassLoader, java.lang.String),直接导致上述的类加载失败问题直接放大了3倍。

假设一次异常栈中有10个类不在PluginClassLoader管控范围内,那么一次log4j的异常栈打印就会触发30次类加载。在加上我们项目中日志文件非常多,一个异常栈打印通常会在多个日志中打印,如一个异常栈会在3个日志文件中打印,那么类加载失败问题再放大3倍,即一次log4j的异常栈打印就会触发90次类加载。那么只需要以10TPS的频率触发调用接口的异常,那么就导致了每秒近1000次的类加载。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
// log4j会对加载失败的类尝试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;
}
}

类加载耗时

分析完日志打印问题,接下来分析类加载问题,为何类加载会消耗这么多资源。截取类加载对CPU消耗采样的火焰图,可见大多数资源消耗在类加载器对类的查找上。另外火焰图中String.relpace方法会消耗近四分之一的CPU挺意外的,因此专门对这处逻辑的代码实现关注了一下,关键代码如下:

image

PluginClassLoader类加载器在查询类之前,会先通过全类名组装文件路径,其中replaceCurrentDir的逻辑则是将/./字符替换成/,仅此简单的逻辑,由于使用的是String.relpace,其底层使用的是正则,因此当调用频率高的场景下,会消耗相当可观的CPU资源。因此这里实际上建议通过类似于replaceParentDir方法的字段截取来实现,能有效降低CPU的资源消耗问题。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
private String normalize(String file) {
int afterLastSeparatorIndex = file.lastIndexOf(SEPARATOR) + SEPARATOR.length();
String afterSeparator = file.substring(afterLastSeparatorIndex);
afterSeparator = replaceParentDir(afterSeparator);
afterSeparator = replaceCurrentDir(afterSeparator);
return new StringBuilder(afterLastSeparatorIndex + afterSeparator.length())
.append(file.substring(0, afterLastSeparatorIndex)).append(afterSeparator).toString();
}

private String replaceParentDir(String file) {
int parentDirIndex;
while ((parentDirIndex = file.indexOf("/../")) >= 0) {
int precedingSlashIndex = file.lastIndexOf('/', parentDirIndex - 1);
if (precedingSlashIndex >= 0) {
file = file.substring(0, precedingSlashIndex) + file.substring(parentDirIndex + 3);
} else {
file = file.substring(parentDirIndex + 4);
}
}
return file;
}

private String replaceCurrentDir(String file) {
return file.replace("/./", "/");
}

主线程耗时

另一个问题,为何启用了日志异步打印,但业务线程依然被日志打印阻塞,从而影响到接口响应耗时?关键代码涉及到log4j异步日志打印时的降级逻辑。简单描述为异步打印日志时有个日志事件队列(默认长度2^18),业务代码的日志事件全部扔到该队列中,由异步线程消费并打印日志。但当日志事件的生产速度大于消费速度,导致该队列的日志时间堆积满后,就会触发降级逻辑,由原先的异步执行降级为通过业务线程同步打印日志。

实现逻辑见com.lmax.disruptor.RingBufferorg.apache.logging.log4j.core.async.AsyncLoggerConfig#callAppenders,与上述类加载问题合并后的具体流程如下图:

image

通过流程图可见,由于ERROR日志异常栈触发的类加载需要对全类名上悲观锁,且类加载过程对CPU资源消耗较多,因此实际场景下虽然log4j有4个异步日志消费线程,但每个类同时只有1个线程在执行加载逻辑,出现传说中的一核有难八核围观的现象。这个悲观锁导致日志消费瓶颈,进一步加剧了日志事件的堆积问题。

当异步队列堆积满后,触发日志打印降级,所有日志变成同步打印后,业务线程同步打印日志会在加载类时等待锁,从而增加了接口耗时,当锁等待超时则直接导致业务接口执行超时。

image

总结

综上是因为大量的业务异常打印了非常多的异常栈日志,在加上项目中配置的异常日志格式为异常栈需要打印jar包名和版本号,导致异常堆栈日志打印时频繁执行无效的类加载过程,而通过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包名称

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

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。即未配置异常输出格式时,默认会通过类加载获取异常堆栈中每个类的包名和版本号。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
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,修改如下:

1
2
3
4
5
<!-- 修改前 -->
<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