But what do you think about includeLocation. Should it override the result of requiresLocation or should the fact that we determined location information is required override the includeLocation setting?
Ralph > On Jul 2, 2019, at 2:34 PM, Matt Sicker <[email protected]> wrote: > > 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] > <mailto:[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 > <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] <mailto:[email protected]>>
