I thought JMH ran your code enough for JIT to take effect (though that’s also up to your warmup iteration setting), and the
On Thu, Jul 4, 2019 at 00:21, Ralph Goers <[email protected]> wrote: > That said, here are the results of the FileAppenderWithLocationBenchmark > from master. > > Benchmark Mode Cnt Score > Error Units > FileAppenderWithLocationBenchmark.log4j1File thrpt 20 27597.034 ± > 350.465 ops/s > FileAppenderWithLocationBenchmark.log4j2File thrpt 20 82966.450 ± > 2023.826 ops/s > FileAppenderWithLocationBenchmark.log4j2RAF thrpt 20 78820.010 ± > 1452.810 ops/s > FileAppenderWithLocationBenchmark.logbackFile thrpt 20 138656.655 ± > 6329.118 ops/s > > and here are the results with all the changes I have made. > > Benchmark Mode Cnt Score > Error Units > FileAppenderWithLocationBenchmark.log4j1File thrpt 20 47003.919 ± > 1594.591 ops/s > FileAppenderWithLocationBenchmark.log4j2File thrpt 20 185129.606 ± > 2309.118 ops/s > FileAppenderWithLocationBenchmark.log4j2RAF thrpt 20 183346.456 ± > 3103.615 ops/s > FileAppenderWithLocationBenchmark.logbackFile thrpt 20 130121.612 ± > 2535.387 ops/s > > Ralph > > > > On Jul 3, 2019, at 8:35 PM, Ralph Goers <[email protected]> > wrote: > > > > Remko, > > > > I ran the existing JHM benchmarks for both no location and with location > and there is still a huge difference. The problem is I don’t necessarily > believe the results. Nor do I think the benchmark I have been using is > totally accurate either. The problem is that, as I understand it, JMH > limits or eliminates much of the optimization the Java runtime will > perform. This is bad for Log4j because in some ways our code is written > inefficiently and hotspot will optimize it. OTOH, since the test is pretty > much logging the same record with an incremented value from the same > location it is hard to say whether the code isn’t being over optimized. I > suspect the real performance will be somewhere in the middle. What would be > better is something like a restful service with plenty of logging driven by > Jmeter once with no location and once with it. > > > > Ralph > > > >> On Jul 2, 2019, at 3:47 PM, Remko Popma <[email protected]> wrote: > >> > >> If memory serves correctly, the `includeLocation` was introduced > because it was necessary for async loggers (and it seemed not feasible to > get this information from the layout pattern). > >> > >> Async loggers need to know upfront whether they need to pass location > information to the consumer thread. > >> > >> If obtaining location information becomes so cheap that it’s > essentially free, it is fine to ignore the `includeLocation` directive and > include location information anyway. > >> > >> About the performance results: what’s the difference between “Log4j 3.0 > with class and method” and “Log4j 3.0 withLocation()”? > >> > >> Also I am generally cautious of custom benchmarks; any reason not to > use JMH? > >> > >> Overall impressive results, congratulations! > >> > >> Remko. > >> > >> (Shameless plug) Every java main() method deserves http://picocli.info > >> > >>> On Jul 3, 2019, at 7:26, Ralph Goers <[email protected]> > wrote: > >>> > >>> 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]>> > >>> > >> > > > > > > > > -- Matt Sicker <[email protected]>
