I have made changes to the code the master branch to measure and improve
performance. I have committed some of the changes but not the last set. I have
not made the latest changes to release-2.x because they will have to be
implemented a bit differently to avoid compatibility issues. The table below
summarizes what I am seeing, at least on my MacBook Pro. This test just
basically writes 1.5 million log statements in a loop using an equivalent
format for each logging framework. Note that JUL is faster with location
information than without primarily because a custom Handler had to be created
to format the log record and it performs better than the one used to log
without location information.
There are several things I should note about this:
• The first step, which is in the PR, has StackLocator.calcLocation
modified to use a faster algorithm. Streams are not particularly fast. This
resulted in some gains not shown here but can be seen in
https://issues.apache.org/jira/browse/LOG4J2-2644
• Performance is proportional to the number of stack traces that need
to be traversed. JUL only had 11 whereas Log4j had 35 before it called
calcLocation. Our stack is very deep because AbstractLogger and LoggerConfig
have been overly refactored along with having to go though several intermediate
objects.
• I introduced a requiredLocation() method throughout the stack. Any
component that requires location information sets this value to true. Based on
this, the call to calcLocation can be made significantly higher up the stack
just before the log event is created but only when a configured component will
use it - with a few exceptions. This code is not yet checked in.
• If for some reason the location information isn’t calculated when the
event is constructed it can still be lazily populated later using the current,
slower mechanism.
As you can see these changes result in a pretty dramatic improvement, almost to
the point that the cost of obtaining location information doesn’t really matter
- especially in Java 11. The results in Java 11 amount to 5us per logging call
with no location vs 7.5us per logging call with location info. These results
could probably be improved even more if AbstractLogger was “flattened” a bit.
I should point out that the logic isn’t perfect. I cannot determine whether
location information is required or not for the RoutingAppender since it
dynamically creates Appenders at run time. Instead, I added a
“requiresLocation” attribute that can be set to indicate that.
However, in testing I have encountered a unit test failure in
RandomAccessFileAppenderTest. It is failing because the location information is
being included even though includeLocation is set to false. I am wondering if
that setting needs to be respected since the pattern specifies including it. It
seems odd to me to not include it in that case.
Thoughts?
Ralph
