基于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
这类问题官方的讨论中也有开发者给出了感叹:除了允许禁用扩展堆栈跟踪信息,或者牺牲多个类加载器存在时的正确性之外,我不确定我们还能做什么。哈哈
以上为个人经验,希望能给大家一个参考,也希望大家多多支持脚本之家。