These benchmarks are impressive! Moving the point of call site calculation is a great idea.
On Tue, 2 Jul 2019 at 16:22, Ralph Goers <[email protected]> wrote: > 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 > -- Matt Sicker <[email protected]>
