Description
"include location" is very expensive operation and has major impact on logging performance.
For Sync logger it is 1.3 - 5 times slower.
For AsyncLogger ( which most of use ) it is 30-100 times slower.
https://logging.apache.org/log4j/2.x/manual/async.html#Location
--> For this reason, asynchronous loggers and asynchronous appenders do not include location information by default.
A new change that was introduced in version 2.17.2, turn on includeLocation for AsyncLogger, although that default is supposed to be true.
This happens when you define the async logger by using AsyncLogger, and not passing a selector, which is not required when explicit define the logger as AsyncLogger in the conf.
Log4j is taking location by calling to StackStreamFactory:: fetchStackFrames (has been changed for log4j since jdk9). JDK 11 seems to have an issue with extensive usage of Stack walking with zgc:
http://mail.openjdk.java.net/pipermail/zgc-dev/2019-March/000605.html
We are not using zge, but I think that also in the bug above they was not able to see it with G1, we experience similar issue with G1. After some time machine CPU can reach to 100%.
With most threads spending time on calclocation:
"CommandExecutor.GetCarpoolStatsRequest.20" #2190 prio=5 os_prio=0 cpu=7522773.26ms elapsed=453703.28s tid=0x00007fab3c007000 nid=0x2a06 runnable [0x00007fa9e8ec9000]
java.lang.Thread.State: RUNNABLE
at java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames(java.base@11.0.14.1/Native Method)
at java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames(java.base@11.0.14.1/StackStreamFactory.java:386)
at java.lang.StackStreamFactory$AbstractStackWalker.getNextBatch(java.base@11.0.14.1/StackStreamFactory.java:322)
at java.lang.StackStreamFactory$AbstractStackWalker.peekFrame(java.base@11.0.14.1/StackStreamFactory.java:263)
at java.lang.StackStreamFactory$AbstractStackWalker.hasNext(java.base@11.0.14.1/StackStreamFactory.java:351)
at java.lang.StackStreamFactory$StackFrameTraverser.tryAdvance(java.base@11.0.14.1/StackStreamFactory.java:593)
at java.util.stream.ReferencePipeline.forEachWithCancel(java.base@11.0.14.1/ReferencePipeline.java:127)
at java.util.stream.AbstractPipeline.copyIntoWithCancel(java.base@11.0.14.1/AbstractPipeline.java:502)
at java.util.stream.AbstractPipeline.copyInto(java.base@11.0.14.1/AbstractPipeline.java:488)
at java.util.stream.AbstractPipeline.wrapAndCopyInto(java.base@11.0.14.1/AbstractPipeline.java:474)
at java.util.stream.FindOps$FindOp.evaluateSequential(java.base@11.0.14.1/FindOps.java:150)
at java.util.stream.AbstractPipeline.evaluate(java.base@11.0.14.1/AbstractPipeline.java:234)
at java.util.stream.ReferencePipeline.findFirst(java.base@11.0.14.1/ReferencePipeline.java:543)
at org.apache.logging.log4j.util.StackLocator.lambda$calcLocation$15(StackLocator.java:100)
at org.apache.logging.log4j.util.StackLocator$$Lambda$127/0x00007fae153164b0.apply(Unknown Source)
at java.lang.StackStreamFactory$StackFrameTraverser.consumeFrames(java.base@11.0.14.1/StackStreamFactory.java:534)
at java.lang.StackStreamFactory$AbstractStackWalker.doStackWalk(java.base@11.0.14.1/StackStreamFactory.java:306)
at java.lang.StackStreamFactory$AbstractStackWalker.callStackWalk(java.base@11.0.14.1/Native Method)
at java.lang.StackStreamFactory$AbstractStackWalker.beginStackWalk(java.base@11.0.14.1/StackStreamFactory.java:370)
at java.lang.StackStreamFactory$AbstractStackWalker.walk(java.base@11.0.14.1/StackStreamFactory.java:243)
at java.lang.StackWalker.walk(java.base@11.0.14.1/StackWalker.java:498)
at org.apache.logging.log4j.util.StackLocator.calcLocation(StackLocator.java:97)
at org.apache.logging.log4j.util.StackLocatorUtil.calcLocation(StackLocatorUtil.java:121)
at org.apache.logging.log4j.core.impl.Log4jLogEvent.getSource(Log4jLogEvent.java:693)
at org.apache.logging.log4j.core.async.AsyncLoggerConfig.populateLazilyInitializedFields(AsyncLoggerConfig.java:171)
at org.apache.logging.log4j.core.async.AsyncLoggerConfig.logToAsyncDelegate(AsyncLoggerConfig.java:151)
at org.apache.logging.log4j.core.async.AsyncLoggerConfig.log(AsyncLoggerConfig.java:133)
at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:666)
at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:635)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:616)
at org.apache.logging.log4j.core.async.AsyncLoggerConfig.log(AsyncLoggerConfig.java:138)
at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:666)
at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:635)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:616)
at org.apache.logging.log4j.core.async.AsyncLoggerConfig.log(AsyncLoggerConfig.java:138)
Starting in version 2.17.2, includelocation is set to true, although by default it is supposed to be false for AsyncLogger.
Why, what has been changed that cause this?
A 2 month ago a change in the creation of LoggerConfig was introduced:
https://github.com/apache/logging-log4j2/commit/5a459dda1e731dfa93198db63493c1cb1cd1e941
With the new change the LoggerConfig is now created by a PluginBuilderFactory and not by a reflection triggering the static createLogger method.
The thing is that there is a change in the inner createlogger implementation.
Until version ( including ) 2.17.1, The createLogger, create an AsyncLoggerConfig with includeLocation param, based on this check includeLocation(includeLocation), which is just a simple check to the value of the param, the param is null, so it creates AsyncLoggerConfig with false includeLocation.
However, In version 2.17.2 the createLogger, evaluate includeLocation value by:
includeLocation(getIncludeLocation(), getConfig())
This method in case of a null value for includeLocationConfigValue ( which is the case in both version ) , determines the includeLocation value based on:
!(context instanceof AsyncLoggerContext);
However, in case that you have mixed loggers or use AsyncLogger, then the context is LoggerContext, although your logger is an async one, so now include location is set to true for your async logger.
2.17.1 stack
return new AsyncLoggerConfig(name, Arrays.asList(refs), filter, level, additivity, properties, config, includeLocation(includeLocation));
at org.apache.logging.log4j.core.async.AsyncLoggerConfig.createLogger(AsyncLoggerConfig.java:272)
at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:136)
2.17.2 stack:
return new AsyncLoggerConfig(name, container.refs, this.getFilter(), container.level, this.isAdditivity(), this.getProperties(), this.getConfig(), AsyncLoggerConfig.includeLocation(this.getIncludeLocation(), this.getConfig()));
at org.apache.logging.log4j.core.async.AsyncLoggerConfig.<init>(AsyncLoggerConfig.java:109)
at org.apache.logging.log4j.core.async.AsyncLoggerConfig$Builder.build(AsyncLoggerConfig.java:88)
at org.apache.logging.log4j.core.async.AsyncLoggerConfig$Builder.build(AsyncLoggerConfig.java:80)
at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:124)
How to reproduce:
Use the following log4j config. Don't pass a selector flag (no need to pass it if logger explicit is defined as AsyncLogger ).
You will find that the AsyncLogger.includeLocation is set to true.
<?xml version="1.0" encoding="UTF-8" ?>
<Configuration>
<Appenders>
<Console name="console" target="SYSTEM_OUT">
<PatternLayout pattern="%d{mm:ss,SSS} [%t] %-5p %c{1} - %m%n" />
</Console>
</Appenders>
<Loggers>
<AsyncRoot level="info">
<AppenderRef ref="console" />
</AsyncRoot>
<AsyncLogger name="com" level="info" />
</Loggers>
</Configuration>
Attachments
Attachments
Issue Links
- relates to
-
LOG4J2-3487 The LoggerConfig includeLocation defaults to true in 2.17.2
-
- Resolved
-