基于Log4j2阻塞業(yè)務(wù)線程引發(fā)的思考
問題描述
問題1
異步日志打印在ringbuffer滿了之后2.7版本的log4j2會默認使用當前線程進行打印日志。
即使不使用默認的策略,2.9之后已經(jīng)改為默認的為enqueue方式,也會因為最后隊列的打滿導致cpu飆高導致業(yè)務(wù)線程卡頓,2.7中隊列使用offer提交日志事件,所以會阻塞
詳細的原因2.7的版本博主已經(jīng)有文章講述,此處不再做過多贅述(//chabaoo.cn/article/232610.htm)
問題2:異常線程棧打印使用討論
首先上官方討論連接:https://issues.apache.org/jira/browse/LOG4J2-2391
異常線程棧的打印導致出現(xiàn)了大量的日志線程出現(xiàn)在load class時的鎖阻塞
官網(wǎng)討論中也指明了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
如果不是異步格式化日志
根據(jù)日志事件LogEvent創(chuàng)建Log4jLogEvent
將Log4jLogEvent嘗試提交至隊列,如果是TransferQueue類型則嘗試轉(zhuǎn)換,否則offer提交至默認的blockingQueue阻塞隊列
如果提交隊列失?。犃袧M了或者其他種種原因)
如果是阻塞類型的Appender則提交給EventRout路由處理日志事件
否則通知異常handle句柄并打印error日志如果存在errorAppender
創(chuàng)建log4j日志事件
Log4jLogEvent根據(jù)日志事件Log4jEvent copy并創(chuàng)建一個final類型的日志對象
Log4jLogEvent序列化日志事件Log4jEvent返回一個日志事件代理LogEventProxy
如果日志事件是Log4jLogEvent類型
調(diào)用事件getThrownProxy方法確認ThrownProxy已經(jīng)完成初始化,如果thrownProxy為空則根據(jù)Thrown創(chuàng)建thrown代理
創(chuàng)建代理并返回
Log4jLogEvent根據(jù)序列化對象將其反序列化為Log4jLogEvent對象
創(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ù)阻塞的堆棧我們可以看到日志阻塞點,我們直奔主題,查看獲取擴展堆棧信息的代碼toExtendedStackTrace
判斷throwable堆棧是否與當前堆棧類名相同,是則使用當前堆棧中class類的CL(classloader)作為lastLoader,使用當前堆棧創(chuàng)建擴展堆棧信息并緩存至extendedStackTrace
如果類名與當前堆棧類不同則根據(jù)類名從map臨時緩存中獲取緩存CacheEntry,根據(jù)緩存創(chuàng)建擴展堆棧信息及更相信lastLoader
否則使用lastLoader按照類名稱加載class類,再根據(jù)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]
而產(chǎn)生大量鎖阻塞的地方就是loadClass部分,根據(jù)進程堆棧中的鎖可以看到正是ClassLoader的鎖位置
protected Class<?> loadClass(String name, boolean resolve)
throws ClassNotFoundException
{
synchronized (getClassLoadingLock(name)) {
...
}
}
產(chǎn)生鎖競爭的原因是因為class名稱相同,那么相同的類名稱為什么會加載多次呢?
為什么同一個類會加載多次?
原因大家應(yīng)該很容易猜到,在不同的classloader中加載同一個類多次是沒毛病的。那么我們進一步分析是解析哪個class時出現(xiàn)了lastLoader找不到的情況。斷點日志查看是這家伙GeneratedMethodAccessor321
GeneratedMethodAccessor類
通過搜索果然根本找不到這個類,于是查詢了一下資料,是JVM對反射調(diào)用的優(yōu)化策略產(chǎn)生的類
如果設(shè)置的不膨脹并且不是VM匿名類,則直接懟反射進行生成字節(jié)碼的方式調(diào)用
否則創(chuàng)建代理訪問反射方法進行調(diào)用。在調(diào)用次數(shù)超過閾值(默認15)時(即發(fā)生膨脹)。對反射方法生成字節(jié)碼并以后采用該方式進行調(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ā)生膨脹超過閾值,并且不是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進行的加載,也就是方法的聲明類
//入?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聲明類,最后一個參數(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不一致就會產(chǎn)生每次出現(xiàn)該異常就會重新加載該類,如果大量的該種情況處的異常出現(xiàn),則會造成極大的性能損耗。
問題總結(jié)
問題1
該問題可以選擇適宜的策略來進行規(guī)避,比如使用Discard模式丟棄隊列滿或者消費繁忙時的日志,并且重寫日志隊列,取消隊列阻塞方式的offer添加
問題2
這類問題官方的討論中也有開發(fā)者給出了感嘆:除了允許禁用擴展堆棧跟蹤信息,或者犧牲多個類加載器存在時的正確性之外,我不確定我們還能做什么。哈哈

以上為個人經(jīng)驗,希望能給大家一個參考,也希望大家多多支持腳本之家。
相關(guān)文章
解決Springboot2.1.x配置Activiti7單獨數(shù)據(jù)源問題
這篇文章主要介紹了Springboot2.1.x配置Activiti7單獨數(shù)據(jù)源問題,非常不錯,具有一定的參考借鑒價值,需要的朋友可以參考下2019-09-09
使用vue3.x+vite+element-ui+vue-router+vuex+axios搭建項目
因為vue3出了一段時間了,element也出了基于vue3.x版本的element-plus,這篇文章就拿他們搭建一個項目,希望能給你帶來幫助2021-08-08

