一個關於log4j2的高併發問題

Apache_Log4j_Logo

原文連接:blog.fliaping.com/a-high-conc…html

前言

日誌應該是一個應用的基礎組件, 其中老牌的log4j應該是咱們用的最多的, 後來互聯網發展,你們都朝着高併發的方向發力,發現log4j性能不行,由於競爭鎖致使阻塞,性能跟不上. 後來其創始人另立門戶logback後, log4j的新主子Apache進行了大的升級改造,就是現在的log4j2, 其異步日誌的性能也是一騎絕塵, 然而其使用過程當中依然有不少坑,稍不留意就會搞我的仰馬翻. 下面先列舉一些別人踩過的log4j的坑:java

問題描述

初級表現

一個APP推送服務,在一次發佈以後, 當遇到批量推送任務時, 線程池打滿, 隊列打滿, 任務堆積. (注: 因爲該次發佈的改動點很普通, 沒有先懷疑該點.)spring

相關環境

  • spring-boot: 1.5.3
  • log4j: 2.7
  • jdk1.8

發佈改動點

  • 新增了一個功能 (和本次內容無關)
  • 在一個類上加了 @RefreshScope 註解

處理流程

  1. 原覺得是第三方接口耗時增長致使的, 監控顯示耗時確實挺高,可是經過ping,curl,網絡監控等手段發現並非接口問題
  2. 閱讀代碼發現那個監控項不只包含了調用第三方接口的耗時,還有其它操做, 遂認爲該監控不可信,再次驗證不是第三方接口,也不是網絡的問題
  3. 發現統計日誌中的兩個時間點差別比較大,居然有三秒. 關鍵是這兩個時間點之間只是拋了個異常,而後打了個日誌
  4. 在代碼中發現log4j2配置用的是同步Logger,異步AsyncAppender,懷疑是高併發時同步日誌產生的阻塞, 將日誌改成配合disrupter的AsyncLogger,結果沒有什麼用
  5. 進行Thread Dump發現不少線程BLOCKED,調用棧顯示確實是與log4j有關, 而且明顯指向和異常棧打印有關
  6. 因爲應用中有不少警告, 而且這些日誌都把異常棧打印出來了. 因而將日誌中沒必要要的異常棧都中止打印, 以後問題解決

問題分析

疑問點

  1. 日誌爲何沒有走異步打印?
  2. 爲何打印異常棧會阻塞? 阻塞在什麼地方?
  3. 爲何會引發阻塞,和發佈的改動點有哪些聯繫?

線程棧分析

如下日誌爲改成異步日誌(AsyncLogger)以後的阻塞線程棧,能夠發現日誌並無用到disruptor這個無鎖庫,而是轉爲了同步Loggerapache

"fastExecutor-670" #2178 prio=5 os_prio=0 tid=0x00007f2d483cd800 nid=0x6026 waiting for monitor entry [0x00007f2c158c3000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:404)
        - waiting to lock <0x0000000088104b60> (a java.lang.Object)
        at org.springframework.boot.loader.LaunchedURLClassLoader.loadClass(LaunchedURLClassLoader.java:94)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
        at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:539)
        at org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace(ThrowableProxy.java:660)
        at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:137)
        at org.springframework.boot.loader.LaunchedURLClassLoader.loadClass(LaunchedURLClassLoader.java:94)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
        at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:539)
        at org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace(ThrowableProxy.java:660)
        at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:137)
        at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:121)
        at org.apache.logging.log4j.core.impl.Log4jLogEvent.getThrownProxy(Log4jLogEvent.java:555)
        at org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(ExtendedThrowablePatternConverter.java:61)
        ... 精簡部分日誌 ...
        at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:447)
        at org.apache.logging.log4j.core.async.AsyncLoggerConfig.callAppendersInCurrentThread(AsyncLoggerConfig.java:105)
        at org.apache.logging.log4j.core.async.EventRoute$2.logMessage(EventRoute.java:65)
        at org.apache.logging.log4j.core.async.AsyncLoggerConfig.callAppenders(AsyncLoggerConfig.java:95)
        at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:432)
        at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:416)
        at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:402)
        at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
        at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2091)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1988)
        at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1960)
        at org.apache.logging.slf4j.Log4jLogger.warn(Log4jLogger.java:259)
        at com.dianwoda.delibird.common.traffic.FastCommander.lambda$runnersEnter$0(FastCommander.java:175)
        at com.dianwoda.delibird.common.traffic.FastCommander$$Lambda$111/638548222.run(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)

複製代碼

如下爲應用異常棧內容bootstrap

com.dianwoda.delibird.common.domain.DeliException:
        at com.dianwoda.delibird.push.manager.PushManager.send(PushManager.java:104) ~[classes!/:?]
        at sun.reflect.GeneratedMethodAccessor119.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 com.dianwoda.delibird.push.manager.PushManager$$EnhancerBySpringCGLIB$$74851038.send(<generated>) ~[classes!/:?]
        at com.dianwoda.delibird.push.provider.DeliPushProviderImpl.lambda$send$0(DeliPushProviderImpl.java:84) ~[classes!/:?]
        at com.dianwoda.delibird.common.tool.DeliRunnable.run(DeliRunnable.java:26) ~[delibird-common-1.0-SNAPSHOT.jar!/:?]
        at com.dianwoda.delibird.common.traffic.FastCommander.lambda$runnersEnter$0(FastCommander.java:173) ~[delibird-common-1.0-SNAPSHOT.jar!/:?]
        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]
複製代碼

疑問點一

日誌爲何沒有走異步打印?api

Log4j2中默認會優先嚐試將LogEvent放入RingBuffer中,若是放不進去(緣由大概是隊列已滿),則會經過AsyncQueueFullPolicy(可自定義)來決策下一步行爲(EventRoute:丟棄 - discard,同步 - synchronous,等待入隊 - enqueue),在log4j-2.7中默認是同步寫日誌(2.9中默認是等待入隊Enqueue的方式),所以,當日志量突增時,異步日誌變同步日誌!緩存

疑問點二

爲何打印異常棧會阻塞? 阻塞在什麼地方?網絡

根據線程棧, 問題主要是由於org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace這個方法. 其中ThrowableProxy這個類是由於LogEvent可能會被跨網絡傳輸,而LogEvent中的異常棧可能不會被另外一端識別,所以須要對異常棧進行從新封裝,會取出棧中異常的jar包及版本等信息。該類的註釋以下:多線程

包裝一個Throwable並添加每一個堆棧跟蹤元素的包信息。
用於在不一樣ClassLoader或JVM中表示Throwable的一個代理,當應用反序列化一個ThrowableProxy, Throwable也許沒有被設置,可是Throwable信息被保存在該代理的其它字段,像 message和stack trace併發

另外該方法是爲了"解析此堆棧跟蹤中與父元素不一樣的全部堆棧條目", 簡單的講,就是把異常堆棧與當前的線程棧做對比,把異常堆棧中不同的類信息解析出來,包括類名,行號,包名,包版本等信息,這時候就須要根據異常棧中的類名獲取Class對象,便須要類加載. 根據線程棧來分析下類加載的過程, 能夠看到阻塞的地方是在等待一個鎖, 正是由於鎖等待致使打印日誌的操做耗時3s.

如下爲阻塞線程的線程棧:

at java.lang.ClassLoader.loadClass(ClassLoader.java:404)
- waiting to lock <0x0000000088104b60> (a java.lang.Object)
at org.springframework.boot.loader.LaunchedURLClassLoader.loadClass(LaunchedURLClassLoader.java:94)
at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:539)
at org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace(ThrowableProxy.java:660)
複製代碼

如下爲類加載獲取鎖的代碼片斷: code-1

// java.lang.ClassLoader#loadClass(java.lang.String, boolean)
protected Class<?> loadClass(String name, boolean resolve)
        throws ClassNotFoundException
    {
        synchronized (getClassLoadingLock(name)) { // 源碼行號:404
            //(1. 注: 先從jvm檢查下類加載過沒有,已加載就直接返回該對象,防止類重複加載)
            // First, check if the class has already been loaded
            Class<?> c = findLoadedClass(name);
            if (c == null) {
                long t0 = System.nanoTime();
                try {
                    // 2. 若是該類加載器有父對象,先用父加載器加載,這就是雙親委派機制
                    if (parent != null) {
                        c = parent.loadClass(name, false);
                    } else {
                        // 3. 若是父加載器加載不到,就用引導加載器加載
                        c = findBootstrapClassOrNull(name);
                    }
                } catch (ClassNotFoundException e) {
                    // ClassNotFoundException thrown if class not found
                    // from the non-null parent class loader
                }

                if (c == null) {
                    // If still not found, then invoke findClass in order
                    // to find the class.
                    long t1 = System.nanoTime();
                    // 4. 若是前面雙親都沒有加載到, 採用當前自定義的findClass加載
                    c = findClass(name); // 源碼行號:424

                    // this is the defining class loader; record the stats
                    sun.misc.PerfCounter.getParentDelegationTime().addTime(t1 - t0);
                    sun.misc.PerfCounter.getFindClassTime().addElapsedTimeFrom(t1);
                    sun.misc.PerfCounter.getFindClasses().increment();
                }
            }
            if (resolve) {
                resolveClass(c);
            }
            return c;
        }
    }
複製代碼

能夠看到類加載的時候會先用檢查下是否已經加載過,加載過就直接返回jvm中的類對象. 若是是走的是獲取加載過的類,應該是很是快的,由於僅僅是一個內存操做,獲取的鎖會被立刻釋放, 在幾千QPS的狀況下根本不可能發生阻塞3s這樣的事情, 那麼此時的類到底有沒有被加載過呢?

能夠看下獲取到該鎖 0x0000000088104b60 的線程棧:

"fastExecutor-671" #1739 prio=5 os_prio=0 tid=0x00007f2d00015000 nid=0x5e64 runnable [0x00007f2c237f9000]
   java.lang.Thread.State: RUNNABLE
        at sun.misc.URLClassPath$Loader.getResource(URLClassPath.java:702)
        at sun.misc.URLClassPath.getResource(URLClassPath.java:212)
        at java.net.URLClassLoader$1.run(URLClassLoader.java:365)
        at java.net.URLClassLoader$1.run(URLClassLoader.java:362)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.net.URLClassLoader.findClass(URLClassLoader.java:361)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
        - locked <0x0000000088104b60> (a java.lang.Object)
        at org.springframework.boot.loader.LaunchedURLClassLoader.loadClass(LaunchedURLClassLoader.java:94)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
        at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:539)
        ... 精簡部份內容 ...
複製代碼

根據上面的線程棧, 獲取鎖以後走到源碼的424行, 就表示類沒有在jvm中加載過,而且雙親加載器也加載不到,調用了findClass去加載. 這裏就很是奇怪了, jvm若是加載過一次,下次必定會從jvm中直接拿到, 結合前面說的鎖會立刻釋放, 根本不會阻塞. 也就是說實際每次要從新加載. 爲了找到具體是哪一個類每次都須要加載一次,須要來debug肯定.

下面是log4j2中 ThrowableProxy 類加載流程的代碼: code-2 ,是調用類加載的地方.

// org.apache.logging.log4j.core.impl.ThrowableProxy#loadClass(java.lang.String)
   /** * Loads classes not located via Reflection.getCallerClass. * * @param lastLoader The ClassLoader that loaded the Class that called this Class. * @param className The name of the Class. * @return The Class object for the Class or null if it could not be located. */
    private Class<?> loadClass(final ClassLoader lastLoader, final String className) {
        // XXX: this is overly complicated (注:確實過於複雜,哈哈哈)
        Class<?> clazz;
        if (lastLoader != null) {
            try {
                // 1. 先用ClassLoader加載一下, 加載上就返回
                clazz = lastLoader.loadClass(className); // 源碼行號: 539
                if (clazz != null) {
                    return clazz;
                }
            } catch (final Throwable ignore) {
                // Ignore exception.
            }
        }
        try {
            // 2. 上一步沒加載上,或者出現異常,用LoaderUtil再次加載(使用Class.forName以及當前線程的ClassLoader)
            clazz = LoaderUtil.loadClass(className);
        } catch (final ClassNotFoundException | NoClassDefFoundError e) {
            // 3. 加載出現異常,再次嘗試一種加載方式
            return loadClass(className);
        } catch (final SecurityException e) {
            return null;
        }
        return clazz;
    }
    // 4. 接上面的3, 再次用當前對象類的加載器加載,出現異常返回空
    private Class<?> loadClass(final String className) {
        try {
            return this.getClass().getClassLoader().loadClass(className);
        } catch (final ClassNotFoundException | NoClassDefFoundError | SecurityException e) {
            return null;
        }
    }
複製代碼

調試過程

先讓代碼跑起來,並走幾回出問題的流程,確保該加載的類已經加載過了, 而後在 code-1findLoadedClass 方法處打斷點並查看返回值是否爲空. code-2lastLoader的類型是LaunchedURLClassLoader 繼承關係以下圖

LaunchedURLClassLoader

loadClass 方法如: code-3 : org.springframework.boot.loader.LaunchedURLClassLoader#loadClass

@Override
protected Class<?> loadClass(String name, boolean resolve)
        throws ClassNotFoundException {
    Handler.setUseFastConnectionExceptions(true);
    try {
        try {
            definePackageIfNecessary(name);
        }
        catch (IllegalArgumentException ex) {
            // Tolerate race condition due to being parallel capable
            if (getPackage(name) == null) {
                // This should never happen as the IllegalArgumentException indicates
                // that the package has already been defined and, therefore,
                // getPackage(name) should not return null.
                throw new AssertionError("Package " + name + " has already been "
                        + "defined but it could not be found");
            }
        }
        return super.loadClass(name, resolve);
    }
    finally {
        Handler.setUseFastConnectionExceptions(false);
    }
}
複製代碼

執行 lastLoader.loadClass(className) 跳到 code-1 , 整個加載流程遵循雙親委派機制, 以下圖

java_classloader_hierarchy

LaunchedURLClassLoader是一個自定義類加載器, 直接調用父類 ClassLoader#loadClasscode-1 中所示, 分別用「應用類加載器」、「擴展類加載器」、「引導類加載器」加載,最終發現了當出現類名 sun.reflect.GeneratedMethodAccessor204 時通過 parent loaders、bootstrap loader、URLClassLoader#findClass都加載不到,最後拋出ClassNotFoundExceptioncode-2 步驟1處捕獲並忽略,接着執行步驟2繼續嘗試加載,隨後拋出異常,捕獲後在步驟3處再次嘗試加載,再次異常返回空。

如異常日誌at sun.reflect.GeneratedMethodAccessor119.invoke(Unknown Source) ~[?:?], 因爲加載不到該類,源碼信息、包信息都是沒有的。

插曲: 調試過程當中重啓了一次應用,發現再也走不到以前的調試邏輯了,好像全部的事情都正常了,沒有加載不上的類了,頓時一臉懵逼。而後誤打誤撞,用一個批量調用的腳本吭哧吭哧一頓調用,而後問題又重現了

在準備看看sun.reflect.GeneratedMethodAccessor204這個類爲何加載不上時,發現根本沒有這個類,一看類名就懷疑是反射生成的類。加上以前的插曲,另外還有別人的提醒,以及google,發現根本緣由竟是jvm對反射的優化策略。

jvm對反射的優化

jvm對待反射有兩種方式:

  1. 使用native方法進行反射操做,這種方式每次執行的速度差很少
  2. 生成bytecode進行反射操做,即生成類sun.reflect.GeneratedMethodAccessor<N>,它是一個被反射調用方法的包裝類,代理不一樣的方法,類後綴序號會遞增。這種方式第一次調用速度較慢,較之第一種會慢3-4倍,可是屢次調用後速度會提高20倍

ReflectionFactory裏有一種機制,就是當一個方法被反射調用的次數超過必定的閥值時(inflationThreshold),會使用第二種方式來提高速度。這個閥值的默認值是15.該閾值能夠經過jvm參數-Dsun.reflect.inflationThreshold進行配置。

那麼爲何log4j2不能加載到生成類sun.reflect.GeneratedMethodAccessor<N>呢?

要回答這個問題就要了解jvm反射實現的第二種方式,jvm會經過方法sun.reflect.ReflectionFactory#newMethodAccessor構建MethodAccessor,代理經過該對象的invoke方法調用真正的方法。下圖爲MethodAccessor接口的相關實現類

MethodAccessor接口的相關實現類

ReflectionFactory#newMethodAccessor代碼以下: code-4

public MethodAccessor newMethodAccessor(Method method) {
        checkInitted();
        // noInflation(不膨脹),直接使用字節碼加強方式
        if (noInflation && !ReflectUtil.isVMAnonymousClass(method.getDeclaringClass())) {
            return new MethodAccessorGenerator().
                generateMethod(method.getDeclaringClass(),
                               method.getName(),
                               method.getParameterTypes(),
                               method.getReturnType(),
                               method.getExceptionTypes(),
                               method.getModifiers());
        } else {
            // 不然使用Inflation膨脹模式, 先建立NativeMethodAccessorImpl,隨後將該實現做爲DelegatingMethodAccessorImpl的一個delegate,實際上仍是委派給NativeMethodAccessorImpl
            NativeMethodAccessorImpl acc =
                new NativeMethodAccessorImpl(method);
            DelegatingMethodAccessorImpl res =
                new DelegatingMethodAccessorImpl(acc);
            acc.setParent(res);
            return res;
        }
}
複製代碼

sun.reflect.NativeMethodAccessorImpl#invoke代碼以下: code-5

public Object invoke(Object obj, Object[] args) throws IllegalArgumentException, InvocationTargetException {
        // We can't inflate methods belonging to vm-anonymous classes because
        // that kind of class can't be referred to by name, hence can't be
        // found from the generated bytecode.(咱們不能膨脹屬於vm-anonymous的類,由於這種類不能經過名字引用,所以不能從生成的字節碼中被發現)
        //
        // 這裏能夠看到,若是調用次數大於inflationThreshold就會膨脹,使用字節碼加強的方式
        if (++numInvocations > ReflectionFactory.inflationThreshold()
                && !ReflectUtil.isVMAnonymousClass(method.getDeclaringClass())) {
            MethodAccessorImpl acc = (MethodAccessorImpl)
                new MethodAccessorGenerator().
                    generateMethod(method.getDeclaringClass(),
                                   method.getName(),
                                   method.getParameterTypes(),
                                   method.getReturnType(),
                                   method.getExceptionTypes(),
                                   method.getModifiers());
            parent.setDelegate(acc);
        }
        // 沒有超過膨脹閾值,就使用JNI方法
        return invoke0(method, obj, args);
}
複製代碼

繼續查看代碼,能夠看到sun.reflect.MethodAccessorGenerator#generate的實現是調用asm字節碼加強工具來生成類,此過程較長,不在此列出。在該方法的最後,咱們發現有這樣一個操做sun.reflect.ClassDefiner#defineClass,查看其源碼

defineClass代碼以下: code-6

/** <P> We define generated code into a new class loader which delegates to the defining loader of the target class. It is necessary for the VM to be able to resolve references to the target class from the generated bytecodes, which could not occur if the generated code was loaded into the bootstrap class loader. </P> <P> There are two primary reasons for creating a new loader instead of defining these bytecodes directly into the defining loader of the target class: first, it avoids any possible security risk of having these bytecodes in the same loader. Second, it allows the generated bytecodes to be unloaded earlier than would otherwise be possible, decreasing run-time footprint. </P> */
    static Class<?> defineClass(String name, byte[] bytes, int off, int len,
                                final ClassLoader parentClassLoader)
    {
        // 建立一個DelegatingClassLoader用來加載生成的類
        ClassLoader newLoader = AccessController.doPrivileged(
            new PrivilegedAction<ClassLoader>() {
                public ClassLoader run() {
                        return new DelegatingClassLoader(parentClassLoader);
                    }
                });
        return unsafe.defineClass(name, bytes, off, len, newLoader, null);
}
複製代碼

經過上面代碼及註釋,發現生成的類是綁定在DelegatingClassLoader這個加載器上的,也就是說只有經過該加載器才能load生成的類,然而在log4j的ThrowableProxy#loadClass方法並無嘗試該類加載器,因此加載不到也是很正常的了。

疑問點三

爲何會引發阻塞,和發佈的改動點有哪些聯繫?

分析至此,引發阻塞的緣由就清楚了,是由於jvm對待反射的優化,使得動態生成的類始終不能經過classLoader加載,因而每次解析異常棧都會進行類加載,而且因爲雙親委派和ThrowableProxy#loadClass的屢次異常處理,致使鎖佔有的時間很長,最終致使阻塞。

關於發佈改動點,就是加上了@RefreshScope註解,經過對比加了和沒加的異常棧日誌,也發現了差異。

沒有加@RefreshScope註解的異常棧:

com.dianwoda.delibird.common.domain.DeliException:
    at com.dianwoda.delibird.push.manager.PushManager.send(PushManager.java:104) ~[classes/:?]
    at com.dianwoda.delibird.push.provider.DeliPushProviderImpl.lambda$send$0(DeliPushProviderImpl.java:84) ~[classes/:?]
    at com.dianwoda.delibird.common.tool.DeliRunnable.run(DeliRunnable.java:26) ~[classes/:?]
    at com.dianwoda.delibird.common.traffic.FastCommander.lambda$runnersEnter$0(FastCommander.java:174) ~[classes/:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_161]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_161]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]
複製代碼

加了@RefreshScope註解的異常棧:

com.dianwoda.delibird.common.domain.DeliException:
    at com.dianwoda.delibird.push.manager.PushManager.send(PushManager.java:104) ~[classes/:?]
    at sun.reflect.GeneratedMethodAccessor204.invoke(Unknown Source) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_161]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_161]
    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 com.dianwoda.delibird.push.manager.PushManager$$EnhancerBySpringCGLIB$$14df0707.send(<generated>) ~[classes/:?]
    at com.dianwoda.delibird.push.provider.DeliPushProviderImpl.lambda$send$0(DeliPushProviderImpl.java:84) ~[classes/:?]
    at com.dianwoda.delibird.common.tool.DeliRunnable.run(DeliRunnable.java:26) ~[classes/:?]
    at com.dianwoda.delibird.common.traffic.FastCommander.lambda$runnersEnter$0(FastCommander.java:174) ~[classes/:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_161]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_161]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]
複製代碼

@RefreshScope的原理

該註解是spring-cloud中用來在配置更新後刷新bean,其原理以下:

  • @RefreshScope 內嵌入了@Scope註解, 用於Spring Scope機制,便是把bean分紅不一樣類型,控制Bean如何經過BeanFactory返回。
  • 經過RefreshScope的父類方法GenericScope#postProcessBeanFactory把本身註冊到beanFactory中,而實現了Scope接口的GenericScope#get的方法,會在get時放入StandardScopeCache緩存中, 其實聲明瞭RefreshScope的bean都是懶加載,在初次使用時才進行建立並緩存。
  • 當調用RefreshScope#refresh方法時,先從緩存中刪除先前的Bean,而後再執行GenericScope.BeanLifecycleWrapper#destroy方法完全結束上一個Bean生命週期,而後再發佈一個RefreshScopeRefreshedEvent事件。
  • 當一個Bean的method被調用的時候,因爲這個bean是被代理的,會觸發org.springframework.aop.framework.CglibAopProxy.DynamicAdvisedInterceptor#intercept方法,方法中會調用org.springframework.aop.target.SimpleBeanTargetSource#getTarget從新生成一個bean 放入 StandardScopeCache中,從而實現了bean更新

從上面的原理看出通過@RefreshScope註解過的bean就是一個代理,這也不難理解爲何會用到反射,而後因爲jvm對反射的優化而產生該問題

總結

該問題的緣由,其實有不少方面:

  1. 從表面看來是加了個@RefreshScope註解致使的
  2. 從自身看來是打了太多異常棧
  3. 從log4j來看是log4j 2.7的隊列滿了以後的默認處理策略問題
  4. 另外對於log4j看來實際上是一個須要優化的地方,對於動態生成的類就應該特殊處理,選擇正確的類加載器,或者不進行類加載

參考

相關文章
相關標籤/搜索