基于Log4j2阻塞業(yè)務(wù)線程引發(fā)的問(wèn)題有哪些

小編給大家分享一下基于Log4j2阻塞業(yè)務(wù)線程引發(fā)的問(wèn)題有哪些，希望大家閱讀完這篇文章之后都有所收獲，下面讓我們一起去探討吧！

問(wèn)題描述

問(wèn)題1

異步日志打印在ringbuffer滿了之后2.7版本的log4j2會(huì)默認(rèn)使用當(dāng)前線程進(jìn)行打印日志。

即使不使用默認(rèn)的策略，2.9之后已經(jīng)改為默認(rèn)的為enqueue方式，也會(huì)因?yàn)樽詈箨?duì)列的打滿導(dǎo)致cpu飆高導(dǎo)致業(yè)務(wù)線程卡頓，2.7中隊(duì)列使用offer提交日志事件，所以會(huì)阻塞

詳細(xì)的原因2.7的版本博主已經(jīng)有文章講述，此處不再做過(guò)多贅述(//kemok4.com/article/232610.htm)

問(wèn)題2：異常線程棧打印使用討論

首先上官方討論連接：https://issues.apache.org/jira/browse/LOG4J2-2391

異常線程棧的打印導(dǎo)致出現(xiàn)了大量的日志線程出現(xiàn)在load class時(shí)的鎖阻塞

官網(wǎng)討論中也指明了ThrowableProxy使用了不正確的CCL(ContextClassLoader)

下面我們分析一下問(wèn)題的原因

ThrowableProxy使用錯(cuò)誤的CCL原因分析

日志詳細(xì)流程不再贅述，直接從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

如果不是異步格式化日志

根據(jù)日志事件LogEvent創(chuàng)建Log4jLogEvent

將Log4jLogEvent嘗試提交至隊(duì)列，如果是TransferQueue類型則嘗試轉(zhuǎn)換，否則offer提交至默認(rèn)的blockingQueue阻塞隊(duì)列

如果提交隊(duì)列失?。?duì)列滿了或者其他種種原因）

如果是阻塞類型的Appender則提交給EventRout路由處理日志事件

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

創(chuàng)建log4j日志事件

Log4jLogEvent根據(jù)日志事件Log4jEvent copy并創(chuàng)建一個(gè)final類型的日志對(duì)象

Log4jLogEvent序列化日志事件Log4jEvent返回一個(gè)日志事件代理LogEventProxy

如果日志事件是Log4jLogEvent類型

調(diào)用事件getThrownProxy方法確認(rèn)ThrownProxy已經(jīng)完成初始化，如果thrownProxy為空則根據(jù)Thrown創(chuàng)建thrown代理

創(chuàng)建代理并返回

Log4jLogEvent根據(jù)序列化對(duì)象將其反序列化為L(zhǎng)og4jLogEvent對(duì)象

創(chuàng)建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);
}

根據(jù)阻塞的堆棧我們可以看到日志阻塞點(diǎn)，我們直奔主題，查看獲取擴(kuò)展堆棧信息的代碼toExtendedStackTrace

判斷throwable堆棧是否與當(dāng)前堆棧類名相同，是則使用當(dāng)前堆棧中class類的CL（classloader）作為lastLoader，使用當(dāng)前堆棧創(chuàng)建擴(kuò)展堆棧信息并緩存至extendedStackTrace

如果類名與當(dāng)前堆棧類不同則根據(jù)類名從map臨時(shí)緩存中獲取緩存CacheEntry，根據(jù)緩存創(chuàng)建擴(kuò)展堆棧信息及更相信lastLoader

否則使用lastLoader按照類名稱加載class類，再根據(jù)class類獲取類位置以及版本信息，如果獲取不到則使用符號(hào)：‘？'代替，例如：

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]

而產(chǎn)生大量鎖阻塞的地方就是loadClass部分，根據(jù)進(jìn)程堆棧中的鎖可以看到正是ClassLoader的鎖位置

protected Class<?> loadClass(String name, boolean resolve)
    throws ClassNotFoundException
{
    synchronized (getClassLoadingLock(name)) {
            ...
    }
}

產(chǎn)生鎖競(jìng)爭(zhēng)的原因是因?yàn)閏lass名稱相同，那么相同的類名稱為什么會(huì)加載多次呢？

為什么同一個(gè)類會(huì)加載多次？

原因大家應(yīng)該很容易猜到，在不同的classloader中加載同一個(gè)類多次是沒(méi)毛病的。那么我們進(jìn)一步分析是解析哪個(gè)class時(shí)出現(xiàn)了lastLoader找不到的情況。斷點(diǎn)日志查看是這家伙GeneratedMethodAccessor321

GeneratedMethodAccessor類

通過(guò)搜索果然根本找不到這個(gè)類，于是查詢了一下資料，是JVM對(duì)反射調(diào)用的優(yōu)化策略產(chǎn)生的類

如果設(shè)置的不膨脹并且不是VM匿名類，則直接懟反射進(jìn)行生成字節(jié)碼的方式調(diào)用

否則創(chuàng)建代理訪問(wèn)反射方法進(jìn)行調(diào)用。在調(diào)用次數(shù)超過(guò)閾值（默認(rèn)15）時(shí)（即發(fā)生膨脹）。對(duì)反射方法生成字節(jié)碼并以后采用該方式進(jìn)行調(diào)用

public MethodAccessor newMethodAccessor(Method var1) {
    checkInitted();
  //不膨脹，直接生成字節(jié)碼方式調(diào)用（并且不是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 {
    //如果調(diào)用次數(shù)發(fā)生膨脹超過(guò)閾值，并且不是VM匿名類，生成字節(jié)碼方式調(diào)用
    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);
    }
    //否則反射調(diào)用
    return invoke0(this.method, var1, var2);
}

繼續(xù)查看生成的字節(jié)碼是如果加載的MethodAccessorGenerator.generateMethod

可以看到一堆ASM字節(jié)碼生成器的代碼拼裝。最后可以看到使用的var1參數(shù)的classloader進(jìn)行的加載，也就是方法的聲明類

//入?yún)ar1是反射調(diào)用的方法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聲明類，最后一個(gè)參數(shù)是使用的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與使用反射調(diào)用的方法聲明類的classloader不一致就會(huì)產(chǎn)生每次出現(xiàn)該異常就會(huì)重新加載該類，如果大量的該種情況處的異常出現(xiàn)，則會(huì)造成極大的性能損耗。

問(wèn)題總結(jié)

問(wèn)題1

該問(wèn)題可以選擇適宜的策略來(lái)進(jìn)行規(guī)避，比如使用Discard模式丟棄隊(duì)列滿或者消費(fèi)繁忙時(shí)的日志，并且重寫日志隊(duì)列，取消隊(duì)列阻塞方式的offer添加

問(wèn)題2

這類問(wèn)題官方的討論中也有開發(fā)者給出了感嘆：除了允許禁用擴(kuò)展堆棧跟蹤信息，或者犧牲多個(gè)類加載器存在時(shí)的正確性之外，我不確定我們還能做什么。哈哈

看完了這篇文章，相信你對(duì)“基于Log4j2阻塞業(yè)務(wù)線程引發(fā)的問(wèn)題有哪些”有了一定的了解，如果想了解更多相關(guān)知識(shí)，歡迎關(guān)注億速云行業(yè)資訊頻道，感謝各位的閱讀！