Log4j2 log PatternLayout configuration effects on SOFAArk PluginClassLoader

This is the first day of my participation in the Gwen Challenge in November. Check out the details: the last Gwen Challenge in 2021

background

"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(AbstractClasspathClassL oader.java:302) at com.alipay.sofa.ark.container.service.classloader.PluginClassLoader.loadClassInternal(PluginClassLoader.java:102) // Plug-in loading at com.alipay.sofa.ark.container.service.classloader.AbstractClasspathClassLoader.loadClass(AbstractClasspathClassLoader.ja va: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(AsyncLoggerConfigDisrupt or.java:112) at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisrupt or.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)Copy the code

Log4j2-related classes are exported in the Sofaark plug-in, so when log4j2 classes need to be loaded, they delegate to PluginClassLoader.

Configure %throwable in PatternLayout to produce different Converter effects

SOFABoot starts executing the configuration file that loads log4j2

Parse the configuration file and create different PCS based on the individual configurations in PatternLayout

Regular mapping list

Find the Converter, then create this object with reflection, and place it in patternConverters.

What circumstance can produce ExtendedThrowablePatternConverter?

There are two conditions that produce this Converter

Configure “xEx”, “xThrowable”, “xException”

If “xEx”, “xThrowable”, and “xException” are configured, rules will be created where converterName matches.

%throwable is created when not configured

Why is that? Let’s look at the next piece of code:

// Create the corresponding PatternFormatter for the PatternLayout to output the log according to the specified rules.
// PatternFormatter relies on Converter to execute the format

// 1. AlwaysWriteExceptions Default to true and can only be changed in the configuration file.
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;
	// All converters corresponding to the current Logger are converters from the above parse pattern
    // The pattern style is generated.
    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;
            // The Throwable handlesThrowable returns true
            So, if there is no %throwable in pattern, false will always be returned
            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 is true when %throwable is configured, otherwise false
    / / that is to say the current Logger without % throwable, creates ExtendedThrowablePatternConverter
    // Handle Converter as the default exception
    if(alwaysWriteExceptions && ! handlesThrowable) {final LogEventPatternConverter pc = ExtendedThrowablePatternConverter.newInstance(config, null);
        list.add(new PatternFormatter(pc, FormattingInfo.getDefault()));
    }
    return list;
}
Copy the code

Conclusion: Generate different types of PatternConverter based on different element types in pattern, If the configuration in the log file % throwable, will create a corresponding ThrowablePatternConverter PatternConverter type. If there is no configuration % throwable, use the default ExtendedThrowablePatternConverter.

Converter difference analysis

The role of the different PatternConverter is to format the corresponding data during log output, so the core method for the corresponding PatternConverter is the format method. See below ThrowablePatternConverter and ExtendedThrowablePatternConverter difference format method.

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); }}Copy the code

The formatOption writes the Throwable stackTracer to the buffer

ExtendedThrowablePatternConverter#format

@Override
public void format(final LogEvent event, final StringBuilder toAppendTo) {
    GetThrownProxy = 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); }}}Copy the code

Final ThrowableProxy proxy = event.getThrownProxy() When a ThrowableProxy object instance is built, a CacheEntry (toExtendedStackTrace) is built to serialize the data in the stack, triggering the classloading action.

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.

Note 1: Wait strategies for Disruptor Consumers

-DAsyncLoggerConfig.WaitStrategy=xxx

The name of the	measures	scenario
BlockingWaitStrategy	lock	Scenarios where CPU resources are scarce and throughput and latency are not important
BusySpinWaitStrategy	The spin	Reduce system calls due to thread switching and reduce latency by constantly retrying. This is recommended when threads are bound to a fixed CPU
PhasedBackoffWaitStrategy	Spin + yield + custom policy	Scenarios where CPU resources are scarce and throughput and latency are not important
SleepingWaitStrategy	Spin plus yield plus sleep	There is a good trade-off between performance and CPU resources. Delay nonuniformity
TimeoutBlockingWaitStrategy	Locked, with a timeout limit	Scenarios where CPU resources are scarce and throughput and latency are not important
YieldingWaitStrategy	Spin plus yield plus spin	There is a good trade-off between performance and CPU resources. Relatively uniform delay

Dark shading is the default policy

Note 2: Disruptor queue length and configure queue blocking discard policy

• – Dlog4j2. AsyncQueueFullPolicy = Default/Discard (Default Default)

• -Dlog4j2.DiscardThreshold=ERROR/INFO/… (the default info)

1, DefaultAsyncQueueFullPolicy – waiting queue, into a synchronous operation strategy (the default)

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
        returnEventRoute.SYNCHRONOUS; }}Copy the code

2, DiscardingAsyncQueueFullPolicy – abandoned log strategy according to the log level

@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);
}
Copy the code

Note 3: Disruptor default queue size

• -DAsyncLogger.RingBufferSize=xxx

// propertyName -> AsyncLoggerConfig.RingBufferSize
static int calculateRingBufferSize(final String propertyName) {
    // Constants.ENABLE_THREADLOCALS Default 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);
}
Copy the code

Constants.ENABLE_THREADLOCALS Is available for web and non-Web applications. The default value is true for non-Web applications and false for Web applications based on Whether the classpath has the javax.servlet. servlet class. This can be set manually by -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.