基于Log4j2阻塞业务线程引发的问题有哪些

2023-06-22 04:06:30 663人浏览泡泡鱼

摘要

小编给大家分享一下基于Log4j2阻塞业务线程引发的问题有哪些，希望大家阅读完这篇文章之后都有所收获，下面让我们一起去探讨吧！问题描述问题1异步日志打印在ringbuffer满了之后2.7版本的log4j2会默认使用当前线程进行打印日志。即

小编给大家分享一下基于Log4j2阻塞业务线程引发的问题有哪些，希望大家阅读完这篇文章之后都有所收获，下面让我们一起去探讨吧！

问题描述

问题1

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

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

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

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

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

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

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

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

ThrowableProxy使用错误的CCL原因分析

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

@Overridepublic 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<Throwable> visited) {    this.throwable = throwable;    this.name = throwable.getClass().getName();    this.message = throwable.getMessage();    this.localizedMessage = throwable.getLocalizedMessage();    final Map<String, CacheEntry> map = new HashMap<>();    final Stack<Class<?>> stack = ReflectionUtil.getCurrentStackTrace();    this.extendedStackTrace = this.toExtendedStackTrace(stack, map, null, throwable.getStackTrace());    final Throwable throwableCause = throwable.getCause();    final Set<Throwable> 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)) {            ...    }}

产生锁竞争的原因是因为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;    }}//NativeMethodAccessorImplpublic 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<MagicAccessorImpl>() {            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<ClassLoader>() {            public ClassLoader run() {                return new DelegatingClassLoader(var4);            }        });        return unsafe.defineClass(var0, var1, var2, var3, var5, (ProtectionDomain)null);    }}

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