基于Log4j2阻塞業務線程引發的問題有哪些

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

問題描述

問題1

異步日志打印在ringbuffer滿了之后2.7版本的log4j2會默認使用當前線程進行打印日志。

即使不使用默認的策略，2.9之后已經改為默認的為enqueue方式，也會因為最后隊列的打滿導致cpu飆高導致業務線程卡頓，2.7中隊列使用offer提交日志事件，所以會阻塞

詳細的原因2.7的版本博主已經有文章講述，此處不再做過多贅述(//www.neiyidaogou.com/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<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;
    }
}
//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<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不一致就會產生每次出現該異常就會重新加載該類，如果大量的該種情況處的異常出現，則會造成極大的性能損耗。

問題總結

問題1

該問題可以選擇適宜的策略來進行規避，比如使用Discard模式丟棄隊列滿或者消費繁忙時的日志，并且重寫日志隊列，取消隊列阻塞方式的offer添加

問題2

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

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