log4j2 日志 PatternLayout 配置对 SOFAArk PluginClassLoader 的影响

log4j2 相关类在 sofaark 插件中是导出的，因此当出现 log4j2 的类需要被加载时，会委托给 PluginClassLoader 进行加载。

背景

"Log4j2-TF-7-AsyncLoggerConfig-8" Id=52 BLOCKED on sun.misc.URLClassPath@26eb1b56 owned by "Log4j2-TF-7-AsyncLoggerConfig-4" Id=17
    at sun.misc.URLClassPath.getNextLoader(URLClassPath.java:479)
    -  blocked on sun.misc.URLClassPath@26eb1b56
    at sun.misc.URLClassPath.getResource(URLClassPath.java:248)
    at java.net.URLClassLoader$1.run(URLClassLoader.java:366)
    at java.net.URLClassLoader$1.run(URLClassLoader.java:363)
    at java.security.AccessController.doPrivileged(Native Method)
    at java.net.URLClassLoader.findClass(URLClassLoader.java:362)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:448)
    at com.alipay.sofa.ark.container.service.classloader.AbstractClasspathClassLoader.resolveLocalClass(AbstractClasspathClassLoader.java:302)
    at com.alipay.sofa.ark.container.service.classloader.PluginClassLoader.loadClassInternal(PluginClassLoader.java:102)
	  // 插件加载  
		at com.alipay.sofa.ark.container.service.classloader.AbstractClasspathClassLoader.loadClass(AbstractClasspathClassLoader.java:71)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:380)
    at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:563)
    at org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace(ThrowableProxy.java:689)
    at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:138)
    at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:122)
    at org.apache.logging.log4j.core.impl.Log4jLogEvent.getThrownProxy(Log4jLogEvent.java:564)
    at org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(ExtendedThrowablePatternConverter.java:63)
    at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:38)
    at org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:333)
    at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:232)
    at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:217)
    at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:57)
    at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:177)
    at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:170)
    at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:161)
    at org.apache.logging.log4j.core.appender.RollingFileAppender.append(RollingFileAppender.java:268)
    at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:448)
    at org.apache.logging.log4j.core.async.AsyncLoggerConfig.asyncCallAppenders(AsyncLoggerConfig.java:115)
    at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:112)
    at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:98)
    at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:128)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:627)
    at java.lang.Thread.run(Thread.java:861)

log4j2 相关类在 sofaark 插件中是导出的，因此当出现 log4j2 的类需要被加载时，会委托给 PluginClassLoader 进行加载。

PatternLayout 中配置 %throwable 对于产生不同 Converter 的影响

SOFABoot 开始执行加载 log4j2 的配置文件

解析配置文件，并根据 PatternLayout 中的各个配置创建不同的 pc

规则映射列表

找到对应 Converter，然后通过反射创建此对象，然后放在 patternConverters 中去。

什么情况下会产生 ExtendedThrowablePatternConverter ？

这里有两个条件会产生这个 Converter

配置 “xEx”, “xThrowable”, “xException”

log4j2 的配置文件中 PatternLayout 如果配置了 “xEx”, “xThrowable”, “xException”，由上面分析可以知道，解析时，rules 哪里匹配到对应 converterName，则会创建。

没有配置 %throwable 时会创建

为什么？来看下一段代码：

// 给 PatternLayout 创建对应的 PatternFormatter，用于在输出日志时按指定的规则输出。
// PatternFormatter 执行 format 要依赖 Converter

// 1.alwaysWriteExceptions 默认为 true, 只能在配置文件中 配置修改。
public List<PatternFormatter> parse(final String pattern, final boolean alwaysWriteExceptions,
           final boolean disableAnsi, final boolean noConsoleNoAnsi) {
    final List<PatternFormatter> list = new ArrayList<>();
    final List<PatternConverter> converters = new ArrayList<>();
    final List<FormattingInfo> fields = new ArrayList<>();

    parse(pattern, converters, fields, disableAnsi, noConsoleNoAnsi, true);

    final Iterator<FormattingInfo> fieldIter = fields.iterator();
    boolean handlesThrowable = false;
	// 当前 Logger 对应的所有 converters 集合，这里的 converters 是从上面 parse pattern 时按照 
    // pattern 的 style 生成的，
    for (final PatternConverter converter : converters) {
        if (converter instanceof NanoTimePatternConverter) {
            // LOG4J2-1074 Switch to actual clock if nanosecond timestamps are required in config.
            // LOG4J2-1248 set config nanoclock
            if (config != null) {
                config.setNanoClock(new SystemNanoClock());
            }
        }
        LogEventPatternConverter pc;
        if (converter instanceof LogEventPatternConverter) { 
            pc = (LogEventPatternConverter) converter;
            // 目前官方提供的 converte在，还有 Throwable 的  handlesThrowable 返回是 true
            // 所以，如果 pattern 中没有 %throwable, 这里会一直返回的都是 false
            handlesThrowable |= pc.handlesThrowable();
        } else {
            pc = new LiteralPatternConverter(config, Strings.EMPTY, true);
        }

        FormattingInfo field;
        if (fieldIter.hasNext()) {
            field = fieldIter.next();
        } else {
            field = FormattingInfo.getDefault();
        }
        list.add(new PatternFormatter(pc, field));
    }
	// alwaysWriteExceptions = true
    // handlesThrowable 在配置 %throwable 时是 true，其他均为 false
    // 也就是说当前 Logger 没有配置 %throwable 时，就会创建 ExtendedThrowablePatternConverter
    // 作为默认的异常处理 Converter
    if (alwaysWriteExceptions && !handlesThrowable) {
        final LogEventPatternConverter pc = ExtendedThrowablePatternConverter.newInstance(config, null);
        list.add(new PatternFormatter(pc, FormattingInfo.getDefault()));
    }
    return list;
}

结论：根据 pattern 中的不同元素类型，产生不同类型的 PatternConverter，如果在日志文件中配置了 %throwable , 则会对应产生一个 ThrowablePatternConverter 类型的 PatternConverter。如果没有配置 %throwable，则默认使用 ExtendedThrowablePatternConverter。

converter 差异分析

不同 PatternConverter 的作用是在日志输出时做相应数据的 format，所以对应 PatternConverter 来说，核心的方法就是 format 方法。下面看 ThrowablePatternConverter 和 ExtendedThrowablePatternConverter 的 format 方法差异。

ThrowablePatternConverter#format

@Override
public void format(final LogEvent event, final StringBuilder buffer) {
    final Throwable t = event.getThrown();

    if (isSubShortOption()) {
        formatSubShortOption(t, getSuffix(event), buffer);
    }
    else if (t != null && options.anyLines()) {
        formatOption(t, getSuffix(event), buffer);
    }
}

formatOption 就是把 Throwable 的 stackTracer 写到 buffer 中

ExtendedThrowablePatternConverter#format

@Override
public void format(final LogEvent event, final StringBuilder toAppendTo) {
    // 这里多了一个 getThrownProxy
    final ThrowableProxy proxy = event.getThrownProxy();
    final Throwable throwable = event.getThrown();
    if ((throwable != null || proxy != null) && options.anyLines()) {
        if (proxy == null) {
            super.format(event, toAppendTo);
            return;
        }
        String suffix = getSuffix(event);
        final String extStackTrace = proxy.getExtendedStackTraceAsString(options.getIgnorePackages(), options.getTextRenderer(), suffix);
        final int len = toAppendTo.length();
        if (len > 0 && !Character.isWhitespace(toAppendTo.charAt(len - 1))) {
            toAppendTo.append(' ');
        }
        if (!options.allLines() || !Strings.LINE_SEPARATOR.equals(options.getSeparator())) {
            final StringBuilder sb = new StringBuilder();
            final String[] array = extStackTrace.split(Strings.LINE_SEPARATOR);
            final int limit = options.minLines(array.length) - 1;
            for (int i = 0; i <= limit; ++i) {
                sb.append(array[i]);
                if (i < limit) {
                    sb.append(options.getSeparator());
                }
            }
            toAppendTo.append(sb.toString());
        } else {
            toAppendTo.append(extStackTrace);
        }
    }
}

final ThrowableProxy proxy = event.getThrownProxy() 结合最上面的异常堆栈来看，在构建 ThrowableProxy 对象实例时会去对堆栈中的数据进行序列化操作构建 CacheEntry（toExtendedStackTrace）,从而触发类加载动作。

A proxy is used to represent a throwable that may not exist in a different class loader or JVM. When an application deserializes a ThrowableProxy, the throwable may not be set, but the throwable’s information is preserved in other fields of the proxy like the message and stack trace.

附1：Disruptor 消费者的等待策略

-DAsyncLoggerConfig.WaitStrategy=xxx

名称	措施	场景
BlockingWaitStrategy	加锁	CPU资源紧缺，吞吐量和延迟并不重要的场景
BusySpinWaitStrategy	自旋	通过不断重试，减少切换线程导致的系统调用，而降低延迟。推荐在线程绑定到固定的CPU的场景下使用
PhasedBackoffWaitStrategy	自旋 + yield + 自定义策略	CPU资源紧缺，吞吐量和延迟并不重要的场景
SleepingWaitStrategy	自旋 + yield + sleep	性能和CPU资源之间有很好的折中。延迟不均匀
TimeoutBlockingWaitStrategy	加锁，有超时限制	CPU资源紧缺，吞吐量和延迟并不重要的场景
YieldingWaitStrategy	自旋 + yield + 自旋	性能和CPU资源之间有很好的折中。延迟比较均匀

深色底纹为默认策略

附2：Disruptor 队列长度并配置队列堵塞丢弃策略

• -Dlog4j2.AsyncQueueFullPolicy=Default/Discard   (默认 Default )

• -Dlog4j2.DiscardThreshold=ERROR/INFO/…    （默认 info)

1、DefaultAsyncQueueFullPolicy—等待队列，转为同步操作策略(默认)

public class DefaultAsyncQueueFullPolicy implements AsyncQueueFullPolicy {
    @Override
    public EventRoute getRoute(final long backgroundThreadId, final Level level) {

        // LOG4J2-1518: prevent deadlock when RingBuffer is full and object being logged calls
        // Logger.log in application thread
        // See also LOG4J2-471: prevent deadlock when RingBuffer is full and object
        // being logged calls Logger.log() from its toString() method in background thread
        return EventRoute.SYNCHRONOUS;
    }
}

2、DiscardingAsyncQueueFullPolicy—按照日志等级抛弃日志策略

@Override
public EventRoute getRoute(final long backgroundThreadId, final Level level) {
    if (level.isLessSpecificThan(thresholdLevel)) {
        if (discardCount.getAndIncrement() == 0) {
            LOGGER.warn("Async queue is full, discarding event with level {}. " +
                        "This message will only appear once; future events from {} " +
                        "are silently discarded until queue capacity becomes available.",
                        level, thresholdLevel);
        }
        return EventRoute.DISCARD;
    }
    return super.getRoute(backgroundThreadId, level);
}

附3：Disruptor 默认队列大小

• -DAsyncLogger.RingBufferSize=xxx

// propertyName -> AsyncLoggerConfig.RingBufferSize
static int calculateRingBufferSize(final String propertyName) {
    // Constants.ENABLE_THREADLOCALS 默认 false
    // RINGBUFFER_NO_GC_DEFAULT_SIZE 4096
    // 256 * 1024=262144
    int ringBufferSize = Constants.ENABLE_THREADLOCALS ? RINGBUFFER_NO_GC_DEFAULT_SIZE : RINGBUFFER_DEFAULT_SIZE;
    final String userPreferredRBSize = PropertiesUtil.getProperties().getStringProperty(propertyName,
                                                                                        String.valueOf(ringBufferSize));
    try {
        int size = Integer.parseInt(userPreferredRBSize);
        // RINGBUFFER_MIN_SIZE=128
        if (size < RINGBUFFER_MIN_SIZE) {
            size = RINGBUFFER_MIN_SIZE;
            LOGGER.warn("Invalid RingBufferSize {}, using minimum size {}.", userPreferredRBSize,
                        RINGBUFFER_MIN_SIZE);
        }
        ringBufferSize = size;
    } catch (final Exception ex) {
        LOGGER.warn("Invalid RingBufferSize {}, using default size {}.", userPreferredRBSize, ringBufferSize);
    }
    return Integers.ceilingNextPowerOfTwo(ringBufferSize);
}

Constants.ENABLE_THREADLOCALS 这个值分为 web 和 非 web 应用两种情况，非 web 应用时，默认是 true，web 应用默认是 false，判断依据是，classpath 是否有 javax.servlet.Servlet 类。可以通过 -Dlog4j2.is.webapp=true/false 来手动设定。

ps: -Dlog4j2.enable.threadlocals：  This system property can be used to switch off the use of threadlocals, which will partly disable Log4j’s garbage-free behaviour: to be fully garbage-free, Log4j stores objects in ThreadLocal fields to reuse them, otherwise new objects are created for each log event. Note that this property is not effective when Log4j detects it is running in a web application.