基于Log4j2阻塞业务线程引发的问题有哪些

魁首哥

作者

基于Log4j2阻塞业务线程引发的问题有哪些

小编给大家分享一下基于Log4j2阻塞业务线程引发的问题有哪些，希望大家阅读完这篇文章之后都有所收获，下面让我们一起去探讨吧！

问题描述

问题1

异步日志打印在ringbuffer满了之后2.7版本的log4j2会默认使用当前线程进行打印日志。

即使不使用默认的策略，2.9之后已经改为默认的为enqueue方式，也会因为最后队列的打满导致cpu飙高导致业务线程卡顿，2.7中队列使用offer提交日志事件，所以会阻塞

详细的原因2.7的版本博主已经有文章讲述，此处不再做过多赘述(//www.yisu.com/article/232610.htm)

问题2：异常线程栈打印使用讨论

首先上官方讨论连接：https://issues.apache.org/jira/browse/LOG4J2-2391

异常线程栈的打印导致出现了大量的日志线程出现在load class时的锁阻塞

官网讨论中也指明了ThrowableProxy使用了不正确的CCL(ContextClassLoader)

下面我们分析一下问题的原因

ThrowableProxy使用错误的CCL原因分析

日志详细流程不再赘述，直接从Appender追加日志梳理

/***Actualwritingoccurshere.**@paramlogEventTheLogEvent.*/@Overridepublicvoidappend(finalLogEventlogEvent){if(!isStarted()){thrownewIllegalStateException("AsyncAppender"+getName()+"isnotactive");}if(!Constants.FORMAT_MESSAGES_IN_BACKGROUND){//LOG4J2-898:usermaychooselogEvent.getMessage().getFormattedMessage();//LOG4J2-763:askmessagetofreezeparameters}finalLog4jLogEventmemento=Log4jLogEvent.createMemento(logEvent,includeLocation);if(!transfer(memento)){if(blocking){//delegatetotheeventrouter(whichmaydiscard,enqueueandblock,orlogincurrentthread)finalEventRouteroute=asyncQueueFullPolicy.getRoute(thread.getId(),memento.getLevel());route.logMessage(this,memento);}else{error("Appender"+getName()+"isunabletowriteprimaryappenders.queueisfull");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代理

privateThrowableProxy(finalThrowablethrowable,finalSet<Throwable>visited){this.throwable=throwable;this.name=throwable.getClass().getName();this.message=throwable.getMessage();this.localizedMessage=throwable.getLocalizedMessage();finalMap<String,CacheEntry>map=newHashMap<>();finalStack<Class<?>>stack=ReflectionUtil.getCurrentStackTrace();this.extendedStackTrace=this.toExtendedStackTrace(stack,map,null,throwable.getStackTrace());finalThrowablethrowableCause=throwable.getCause();finalSet<Throwable>causeVisited=newHashSet<>(1);this.causeProxy=throwableCause==null?null:newThrowableProxy(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的锁位置

protectedClass<?>loadClass(Stringname,booleanresolve)throwsClassNotFoundException{synchronized(getClassLoadingLock(name)){...}}

产生锁竞争的原因是因为class名称相同，那么相同的类名称为什么会加载多次呢？

为什么同一个类会加载多次？

原因大家应该很容易猜到，在不同的classloader中加载同一个类多次是没毛病的。那么我们进一步分析是解析哪个class时出现了lastLoader找不到的情况。断点日志查看是这家伙GeneratedMethodAccessor321

GeneratedMethodAccessor类

通过搜索果然根本找不到这个类，于是查询了一下资料，是JVM对反射调用的优化策略产生的类

如果设置的不膨胀并且不是VM匿名类，则直接怼反射进行生成字节码的方式调用

否则创建代理访问反射方法进行调用。在调用次数超过阈值（默认15）时（即发生膨胀）。对反射方法生成字节码并以后采用该方式进行调用

publicMethodAccessornewMethodAccessor(Methodvar1){checkInitted();//不膨胀，直接生成字节码方式调用（并且不是VM匿名类）if(noInflation&&!ReflectUtil.isVMAnonymousClass(var1.getDeclaringClass())){return(newMethodAccessorGenerator()).generateMethod(var1.getDeclaringClass(),var1.getName(),var1.getParameterTypes(),var1.getReturnType(),var1.getExceptionTypes(),var1.getModifiers());}else{NativeMethodAccessorImplvar2=newNativeMethodAccessorImpl(var1);DelegatingMethodAccessorImplvar3=newDelegatingMethodAccessorImpl(var2);var2.setParent(var3);returnvar3;}}//NativeMethodAccessorImplpublicObjectinvoke(Objectvar1,Object[]var2)throwsIllegalArgumentException,InvocationTargetException{//如果调用次数发生膨胀超过阈值，并且不是VM匿名类，生成字节码方式调用if(++this.numInvocations>ReflectionFactory.inflationThreshold()&&!ReflectUtil.isVMAnonymousClass(this.method.getDeclaringClass())){MethodAccessorImplvar3=(MethodAccessorImpl)(newMethodAccessorGenerator()).generateMethod(this.method.getDeclaringClass(),this.method.getName(),this.method.getParameterTypes(),this.method.getReturnType(),this.method.getExceptionTypes(),this.method.getModifiers());this.parent.setDelegate(var3);}//否则反射调用returninvoke0(this.method,var1,var2);}

继续查看生成的字节码是如果加载的MethodAccessorGenerator.generateMethod

可以看到一堆ASM字节码生成器的代码拼装。最后可以看到使用的var1参数的classloader进行的加载，也就是方法的声明类

//入参var1是反射调用的方法method的声明类(MethodAccessorImpl)(newMethodAccessorGenerator()).generateMethod(this.method.getDeclaringClass(),this.method.getName(),this.method.getParameterTypes(),this.method.getReturnType(),this.method.getExceptionTypes(),this.method.getModifiers());privateMagicAccessorImplgenerate(finalClass<?>var1,Stringvar2,Class<?>[]var3,Class<?>var4,Class<?>[]var5,intvar6,booleanvar7,booleanvar8,Class<?>var9){ByteVectorvar10=ByteVectorFactory.create();this.asm=newClassFileAssembler(var10);...return(MagicAccessorImpl)AccessController.doPrivileged(newPrivilegedAction<MagicAccessorImpl>(){publicMagicAccessorImplrun(){try{//使用ClassDefiner声明类，最后一个参数是使用的var1的classloader，也就是反射方法声明类的classloaderreturn(MagicAccessorImpl)ClassDefiner.defineClass(var13,var17,0,var17.length,var1.getClassLoader()).newInstance();}catch(IllegalAccessException|InstantiationExceptionvar2){thrownewInternalError(var2);}}});}}classClassDefiner{staticfinalUnsafeunsafe=Unsafe.getUnsafe();staticClass<?>defineClass(Stringvar0,byte[]var1,intvar2,intvar3,finalClassLoadervar4){//DelegatingClassLoader代理classloader直接委派原classloader加载//即：使用声明方法类的classloader加载ClassLoadervar5=(ClassLoader)AccessController.doPrivileged(newPrivilegedAction<ClassLoader>(){publicClassLoaderrun(){returnnewDelegatingClassLoader(var4);}});returnunsafe.defineClass(var0,var1,var2,var3,var5,(ProtectionDomain)null);}}

那么如果lastLoader也就是堆栈的上一层的classloader与使用反射调用的方法声明类的classloader不一致就会产生每次出现该异常就会重新加载该类，如果大量的该种情况处的异常出现，则会造成极大的性能损耗。