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.