基于Log4j2阻塞业务线程引发的思考

基于Log4j2阻塞业务线程引发的思考

目录问题描述问题1问题2：异常线程栈打印使用讨论ThrowableProxy使用错误的CCL原因分析异步Appender追加日志创建log4j日志事件创建ThrownProxy代理为什么同一个类会加载多次？GeneratedMethodAccessor类问题总结问题1问题2

问题描述

问题1

异步日志打印在ringbuffer满了之后2.7版本的log4j2会默认使用当前线程进行打印日志。

即使不使用默认的策略，2.9之后已经改为默认的为enqueue方式，也会因为最后队列的打满导致cpu飙高导致业务线程卡顿，2.7中队列使用offer提交日志事件，所以会阻塞

详细的原因2.7的版本博主已经有文章讲述，此处不再做过多赘述(//jb51.net/article/232610.htm)

问题2：异常线程栈打印使用讨论

首先上官方讨论连接：https://issues.apache.org/jira/browse/LOG4J2-2391

异常线程栈的打印导致出现了大量的日志线程出现在load class时的锁阻塞

官网讨论中也指明了ThrowableProxy使用了不正确的CCL(ContextClassLoader)

下面我们分析一下问题的原因

ThrowableProxy使用错误的CCL原因分析

日志详细流程不再赘述，直接从Appender追加日志梳理

/**

* Actual writing occurs here.

*

* @param logEvent The LogEvent.

*/

@Override

public void append(final LogEvent logEvent) {

if (!isStarted()) {

throw new IllegalStateException("AsyncAppender " + getName() + " is not active");

}

if (!Constants.FORMAT_MESSAGES_IN_BACKGROUND) { // LOG4J2-898: user may choose

logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters

}

final Log4jLogEvent memento = Log4jLogEvent.createMemento(logEvent, includeLocation);

if (!transfer(memento)) {

if (blocking) {

// delegate to the event router (which may discard, enqueue and block, or log in current thread)

final EventRoute route = asyncQueueFullPolicy.getRoute(thread.getId(), memento.getLevel());

route.logMessage(this, memento);

} else {

error("Appender " + getName() + " is unable to write primary appenders. queue is full");

logToErrorAppenderIfNecessary(false, memento);

}

}

}

异步Appender追加日志

异步Appender追加日志AsyncAppender.append

如果不是异步格式化日志

根据日志事件LogEvent创建Log4jLogEvent

将Log4jLogEvent尝试提交至队列，如果是TransferQueue类型则尝试转换，否则offer提交至默认的blockingQueue阻塞队列

如果提交队列失败（队列满了或者其他种种原因）

如果是阻塞类型的Appender则提交给EventRout路由处理日志事件

否则通知异常handle句柄并打印error日志如果存在errorAppender

创建log4j日志事件

Log4jLogEvent根据日志事件Log4jEvent copy并创建一个final类型的日志对象

Log4jLogEvent序列化日志事件Log4jEvent返回一个日志事件代理LogEventProxy

如果日志事件是Log4jLogEvent类型

调用事件getThrownProxy方法确认ThrownProxy已经完成初始化，如果thrownProxy为空则根据Thrown创建thrown代理

创建代理并返回

Log4jLogEvent根据序列化对象将其反序列化为Log4jLogEvent对象

创建ThrownProxy代理

private ThrowableProxy(final Throwable throwable, final Set visited) {

this.throwable = throwable;

this.name = throwable.getClass().getName();

this.message = throwable.getMessage();

this.localizedMessage = throwable.getLocalizedMessage();

final Map map = new HashMap<>();

final Stack> stack = ReflectionUtil.getCurrentStackTrace();

this.extendedStackTrace = this.toExtendedStackTrace(stack, map, null, throwable.getStackTrace());

final Throwable throwableCause = throwable.getCause();

final Set causeVisited = new HashSet<>(1);

this.causeProxy = throwableCause == null ? null : new ThrowableProxy(throwable, stack, map, throwableCause,

visited, causeVisited);

this.suppressedProxies = this.toSuppressedProxies(throwable, visited);

}

根据阻塞的堆栈我们可以看到日志阻塞点，我们直奔主题，查看获取扩展堆栈信息的代码toExtendedStackTrace

判断throwable堆栈是否与当前堆栈类名相同，是则使用当前堆栈中class类的CL（classloader）作为lastLoader，使用当前堆栈创建扩展堆栈信息并缓存至extendedStackTrace

如果类名与当前堆栈类不同则根据类名从map临时缓存中获取缓存CacheEntry，根据缓存创建扩展堆栈信息及更相信lastLoader

否则使用lastLoader按照类名称加载class类，再根据class类获取类位置以及版本信息，如果获取不到则使用符号：‘？'代替，例如：

at sun.reflect.GeneratedMethodAccessor321.invoke(Unknown Source) ~[?:?]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_77]

at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_77]

at org.springframework.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:216) ~[spring-core-4.3.15.RELEASE.jar!/:4.3.15.RELEASE]

at org.springframework.cloud.context.scope.GenericScope$LockedScopedProxyFactoryBean.invoke(GenericScope.java:472) ~[spring-cloud-context-1.3.3.RELEASE.jar!/:1.3.3.RELEASE]

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.15.RELEASE.jar!/:4.3.15.RELEASE]

at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673) ~[spring-aop-4.3.15.RELEASE.jar!/:4.3.15.RELEASE]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_77]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_77]

at java.lang.Thread.run(Thread.java:745) [?:1.8.0_77]

而产生大量锁阻塞的地方就是loadClass部分，根据进程堆栈中的锁可以看到正是ClassLoader的锁位置

protected Class> loadClass(String name, boolean resolve)

throws ClassNotFoundException

{

synchronized (getClassLoadingLock(name)) {http://

...

}

}

产生锁竞争的原因是因为class名称相同，那么相同的类名称为什么会加载多次呢？

为什么同一个类会加载多次？

原因大家应该很容易猜到，在不同的classloader中加载同一个类多次是没毛病的。那么我们进一步分析是解析哪个class时出现了lastLoader找不到的情况。断点日志查看是这家伙GeneratedMethodAccessor321

GeneratedMethodAccessor类

通过搜索果然根本找不到这个类，于是查询了一下资料，是JVM对反射调用的优化策略产生的类

如果设置的不膨胀并且不是VM匿名类，则直接怼反射进行生成字节码的方式调用

否则创建代理访问反射方法进行调用。在调用次数超过阈值（默认15）时（即发生膨胀）。对反射方法生成字节码并以后采用该方式进行调用

public MethodAccessor newMethodAccessor(Method var1) {

checkInitted();

//不膨胀，直接生成字节码方式调用（并且不是VM匿名类）

if (noInflation && !ReflectUtil.isVMAnonymousClass(var1.getDeclaringClass())) {

return (new MethodAccessorGenerator()).generateMethod(var1.getDeclaringClass(), var1.getName(), var1.getParameterTypes(), var1.getReturnType(), var1.getExceptionTypes(), var1.getModifiers());

} else {

NativeMethodAccessorImpl var2 = new NativeMethodAccessorImpl(var1);

DelegatingMethodAccessorImpl var3 = new DelegatingMethodAccessorImpl(var2);

var2.setParent(var3);

return var3;

}

}

//NativeMethodAccessorImpl

public Object invoke(Object var1, Object[] var2) throws IllegalArgumentException, InvocationTargetException {

//如果调用次数发生膨胀超过阈值，并且不是VM匿名类，生成字节码方式调用

if (++this.numInvocations > ReflectionFactory.inflationThreshold() && !ReflectUtil.isVMAnonymousClass(this.method.getDeclaringClass())) {

MethodAccessorImpl var3 = (MethodAccessorImpl)(new MethodAccessorGenerator()).generateMethod(this.method.getDeclaringClass(), this.method.getName(), this.method.getParameterTypes(), this.method.getReturnType(), this.method.getExceptionTypes(), this.method.getModifiers());

this.parent.setDelegate(var3);

}

//否则反射调用

return invoke0(this.method, var1, var2);

}

继续查看生成的字节码是如果加载的MethodAccessorGenerator.generateMethod

可以看到一堆ASM字节码生成器的代码拼装。最后可以看到使用的var1参数的classloader进行的加载，也就是方法的声明类

//入参var1是反射调用的方法method的声明类

(MethodAccessorImpl)(new MethodAccessorGenerator()).generateMethod(this.method.getDeclaringClass(), this.method.getName(), this.method.getParameterTypes(), this.method.getReturnType(), this.method.getExceptionTypes(), this.method.getModifiers());

private MagicAccessorImpl generate(final Class> var1, String var2, Class>[] var3, Class> var4, Class>[] var5, int var6, boolean var7, boolean var8, Class> var9) {

ByteVector var10 = ByteVectorFactory.create();

this.asm = new ClassFileAssembler(var10);

...

return (MagicAccessorImpl)AccessController.doPrivileged(new PrivilegedAction() {

public MagicAccessorImpl run() {

try {

//使用ClassDefiner声明类，最后一个参数是使用的var1的classloader，也就是反射方法声明类的classloader

return (MagicAccessorImpl)ClassDefiner.defineClass(var13, var17, 0, var17.length, var1.getClassLoader()).newInstance();

} catch (IllegalAccessException | InstantiationException var2) {

throw new InternalError(var2);

}

}

});

}

}

class ClassDefiner {

static final Unsafe unsafe = Unsafe.getUnsafe();

static Class> defineClass(String var0, byte[] var1, int var2, int var3, final ClassLoader var4) {

//DelegatingClassLoader代理classloader直接委派原classloader加载

//即：使用声明方法类的classloader加载

ClassLoader var5 = (ClassLoader)AccessController.doPrivileged(new PrivilegedAction() {

public ClassLoader run() {

return new DelegatingClassLoader(var4);

}

});

return unsafe.defineClass(var0, var1, var2, var3, var5, (ProtectionDomain)null);

}

}

那么如果lastLoader也就是堆栈的上一层的classloader与使用反射调用的方法声明类的classloader不一致就会产生每次出现该异常就会重新加载该类，如果大量的该种情况处的异常出现，则会造成极大的性能损耗。

问题总结

问题1

该问题可以选择适宜的策略来进行规避，比如使用Discard模式丢弃队列满或者消费繁忙时的日志，并且重写日志队列，取消队列阻塞方式的offer添加

问题2

这类问题官方的讨论中也有开发者给出了感叹：除了允许禁用扩展堆栈跟踪信息，或者牺牲多个类加载器存在时的正确性之外，我不确定我们还能做什么。哈哈

版权声明：本文内容由网络用户投稿，版权归原作者所有，本站不拥有其著作权，亦不承担相应法律责任。如果您发现本站中有涉嫌抄袭或描述失实的内容，请联系我们jiasou666@gmail.com 处理，核实后本网站将在24小时内删除侵权内容。