基於Log4j2阻塞業務線程引發的思考
問題描述
問題1
異步日志打印在ringbuffer滿瞭之後2.7版本的log4j2會默認使用當前線程進行打印日志。
即使不使用默認的策略,2.9之後已經改為默認的為enqueue方式,也會因為最後隊列的打滿導致cpu飆高導致業務線程卡頓,2.7中隊列使用offer提交日志事件,所以會阻塞
詳細的原因2.7的版本博主已經有文章講述,此處不再做過多贅述(//www.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<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
這類問題官方的討論中也有開發者給出瞭感嘆:除瞭允許禁用擴展堆棧跟蹤信息,或者犧牲多個類加載器存在時的正確性之外,我不確定我們還能做什麼。哈哈
以上為個人經驗,希望能給大傢一個參考,也希望大傢多多支持WalkonNet。
推薦閱讀:
- Java動態代理簡單介紹
- 如何自定義feign調用實現hystrix超時、異常熔斷
- java類加載機制、類加載器、自定義類加載器的案例
- 詳解Mybatis內的mapper方法為何不能重載
- 解析動態代理jdk的Proxy與spring的CGlib(包括區別介紹)