Logback 1.2 has been released. I just ran our performance benchmarks against it and I am mystified. Logback 1.2 is coming out almost 4 times slower than 1.1.10. Can someone please verify my results?
I am running them with java -jar target/benchmarks.jar ".*FileAppenderBenchmark.*" -f 1 -wi 10 -i 10 -t 4 -tu ms This is on my MacBook Pro (mid-2015) with a 2.8 GHz Intel Core i7 and a fast SSD. Benchmark Mode Samples Score Error Units o.a.l.l.p.j.FileAppenderBenchmark.julFile thrpt 10 94.052 ± 13.645 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.log4j1File thrpt 10 838.130 ± 11.205 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.log4j2File thrpt 10 1844.284 ± 72.803 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.log4j2MMF thrpt 10 2041.727 ± 1260.868 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.log4j2RAF thrpt 10 1879.691 ± 93.162 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.logbackFile thrpt 10 287.678 ± 8.516 ops/ms This is on a Mac Pro (mid-2013) with a 3.5 GHz Intel 6 Core Xeon E5 with an external USB SSD. Benchmark Mode Samples Score Error Units o.a.l.l.p.j.FileAppenderBenchmark.julFile thrpt 10 67.616 ± 8.256 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.log4j1File thrpt 10 607.507 ± 87.307 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.log4j2File thrpt 10 668.316 ± 124.457 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.log4j2MMF thrpt 10 3174.031 ± 149.277 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.log4j2RAF thrpt 10 839.811 ± 154.662 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.logbackFile thrpt 10 175.482 ± 0.869 ops/ms This is also on the same Map Pro (mid-2013) but using the faster internal SSD. Benchmark Mode Samples Score Error Units o.a.l.l.p.j.FileAppenderBenchmark.julFile thrpt 10 75.435 ± 0.287 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.log4j1File thrpt 10 735.162 ± 5.182 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.log4j2File thrpt 10 1346.217 ± 13.955 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.log4j2MMF thrpt 10 2439.903 ± 355.553 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.log4j2RAF thrpt 10 1507.775 ± 9.600 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.logbackFile thrpt 10 184.796 ± 2.052 ops/ms Finally, this is on my old MacBook Pro (Late-2011) 2.5GHz Intel Core i5 with an internal hard drive. Benchmark Mode Samples Score Error Units o.a.l.l.p.j.FileAppenderBenchmark.julFile thrpt 10 39.181 ± 3.315 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.log4j1File thrpt 10 485.160 ± 98.892 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.log4j2File thrpt 10 551.578 ± 120.902 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.log4j2MMF thrpt 10 1720.083 ± 1113.734 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.log4j2RAF thrpt 10 561.398 ± 226.339 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.logbackFile thrpt 10 161.530 ± 4.585 ops/ms The news page at Logback says that it has major performance improvements but these numbers are 3-4 times slower than what I got with 1.1.10. Ralph > On Feb 8, 2017, at 10:31 AM, Apache <ralph.go...@dslextreme.com> wrote: > > I’m pretty sure the problem we have is that a) we are synchronizing many > methods and b) we are synchronizing more than just the write. Unfortunately, > I can’t figure out how to reduce that based on how dispersed the code has > gotten. > > Ralph > >> On Feb 8, 2017, at 10:14 AM, Apache <ralph.go...@dslextreme.com >> <mailto:ralph.go...@dslextreme.com>> wrote: >> >> I tried to modify FileManager to just use a BufferedOutputStream but >> discovered I couldn’t as the layouts now require the ByteBuffer. >> >> Ralph >> >>> On Feb 8, 2017, at 12:14 AM, Apache <ralph.go...@dslextreme.com >>> <mailto:ralph.go...@dslextreme.com>> wrote: >>> >>> The append method isn’t synchronized but the writeBytes method acquires a >>> lock. His code is actually a lot simpler than ours in that it just uses a >>> BufferedOutputStream and he only obtains the lock when he is writing to it. >>> >>> Ralph >>> >>>> On Feb 6, 2017, at 5:23 PM, Matt Sicker <boa...@gmail.com >>>> <mailto:boa...@gmail.com>> wrote: >>>> >>>> I'm not sure if I'm looking in the right place, but a major difference now >>>> between Logback's appenders and Log4j's is that Logback isn't synchronized >>>> on the append method. >>>> >>>> On 6 February 2017 at 18:18, Matt Sicker <boa...@gmail.com >>>> <mailto:boa...@gmail.com>> wrote: >>>> Is this something we can improve performance on by implementing a file >>>> appender based on FileChannel or AsynchronousFileChannel instead of >>>> OutputStream? >>>> >>>> On 6 February 2017 at 17:50, Apache <ralph.go...@dslextreme.com >>>> <mailto:ralph.go...@dslextreme.com>> wrote: >>>> Ceki has updated his numbers to include those reported on the mailing >>>> list. >>>> https://docs.google.com/spreadsheets/d/1cpb5D7qnyye4W0RTlHUnXedYK98catNZytYIu5D91m0/edit#gid=0 >>>> >>>> <https://docs.google.com/spreadsheets/d/1cpb5D7qnyye4W0RTlHUnXedYK98catNZytYIu5D91m0/edit#gid=0> >>>> >>>> I haven’t run the tests with Logback 1.2-SNAPSHOT but my numbers for my >>>> two MacBooks are at >>>> https://docs.google.com/spreadsheets/d/1L67IhmUVvyLBWtC6iq0TMj-j0vrbKsUKWuZV0Nlqisk/edit?usp=sharing >>>> >>>> <https://docs.google.com/spreadsheets/d/1L67IhmUVvyLBWtC6iq0TMj-j0vrbKsUKWuZV0Nlqisk/edit?usp=sharing>. >>>> >>>> >>>> Ralph >>>> >>>>> On Feb 6, 2017, at 9:33 AM, Apache <ralph.go...@dslextreme.com >>>>> <mailto:ralph.go...@dslextreme.com>> wrote: >>>>> >>>>> Yes, that is still the standard approach most people use and is the only >>>>> way to provide a head-to-head comparison against the logging frameworks. >>>>> >>>>> Ralph >>>>> >>>>>> On Feb 6, 2017, at 8:02 AM, Matt Sicker <boa...@gmail.com >>>>>> <mailto:boa...@gmail.com>> wrote: >>>>>> >>>>>> This is all in a synchronous appender, right? Either way, that's rather >>>>>> interesting. >>>>>> >>>>>> On 6 February 2017 at 07:54, Apache <ralph.go...@dslextreme.com >>>>>> <mailto:ralph.go...@dslextreme.com>> wrote: >>>>>> Someone posted numbers on the Logback user’s list that match mine. It >>>>>> shows Logback 1.1.9 was pretty terrible, 1.1.10 is somewhat better and >>>>>> 1.2-SNAPSHOT is on par or slightly better than Log4j 2. >>>>>> >>>>>> Ralph >>>>>> >>>>>>> On Feb 5, 2017, at 3:25 PM, Matt Sicker <boa...@gmail.com >>>>>>> <mailto:boa...@gmail.com>> wrote: >>>>>>> >>>>>>> I think we need some comparisons on the log4j side: file appender with >>>>>>> 256k buffer size, random access file appender with 256k buffer size >>>>>>> (which appears to be the default), and memory mapped file appender. >>>>>>> It'd be cool to see how these compose with async logging enabled in >>>>>>> both log4j and logback. >>>>>>> >>>>>>> On 5 February 2017 at 16:06, Apache <ralph.go...@dslextreme.com >>>>>>> <mailto:ralph.go...@dslextreme.com>> wrote: >>>>>>> You should run the code at https://github.com/ceki/logback-perf >>>>>>> <https://github.com/ceki/logback-perf> to compare your results to >>>>>>> Ceki’s. You also should capture the cpubenchmark speed of your >>>>>>> processor and get the speed of your hard drive. I used Blackmagic speed >>>>>>> test on my Mac. I am capturing my results in a Google spreadsheet. I >>>>>>> will post the like once I have it. >>>>>>> >>>>>>> Ralph >>>>>>> >>>>>>>> On Feb 5, 2017, at 1:48 PM, Gary Gregory <garydgreg...@gmail.com >>>>>>>> <mailto:garydgreg...@gmail.com>> wrote: >>>>>>>> >>>>>>>> If you want, I can run tests on Windows once the build works on >>>>>>>> Windows again. >>>>>>>> >>>>>>>> Let me know what args/command line... >>>>>>>> >>>>>>>> Gary >>>>>>>> >>>>>>>> On Feb 5, 2017 11:58 AM, "Apache" <ralph.go...@dslextreme.com >>>>>>>> <mailto:ralph.go...@dslextreme.com>> wrote: >>>>>>>> I guess my MacBook Pro must fit in the Slow CPU/Fast Hard drive >>>>>>>> category. With Logback 1.10 and -t 4 now get >>>>>>>> >>>>>>>> Benchmark Mode Samples >>>>>>>> Score Error Units >>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.julFile thrpt 20 >>>>>>>> 98187.673 ± 4935.712 ops/s >>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j1File thrpt 20 >>>>>>>> 842374.496 ± 6762.712 ops/s >>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2File thrpt 20 >>>>>>>> 1853062.583 ± 67032.225 ops/s >>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2RAF thrpt 20 >>>>>>>> 2036011.226 ± 53208.281 ops/s >>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.logbackFile thrpt 20 >>>>>>>> 999667.438 ± 12074.003 ops/s >>>>>>>> >>>>>>>> I’ll have to try this on one my VMs at work. We don’t run anything >>>>>>>> directly on bare metal any more. >>>>>>>> >>>>>>>> Ralph >>>>>>>> >>>>>>>>> On Feb 5, 2017, at 9:40 AM, Apache <ralph.go...@dslextreme.com >>>>>>>>> <mailto:ralph.go...@dslextreme.com>> wrote: >>>>>>>>> >>>>>>>>> Ceki finally fixed some of the performance problems in the >>>>>>>>> FileAppender. See https://logback.qos.ch/news.html >>>>>>>>> <https://logback.qos.ch/news.html> and >>>>>>>>> https://docs.google.com/spreadsheets/d/1cpb5D7qnyye4W0RTlHUnXedYK98catNZytYIu5D91m0/edit#gid=0 >>>>>>>>> >>>>>>>>> <https://docs.google.com/spreadsheets/d/1cpb5D7qnyye4W0RTlHUnXedYK98catNZytYIu5D91m0/edit#gid=0>. >>>>>>>>> I suspect we have a few optimizations we can make. >>>>>>>>> >>>>>>>>> Ralph >>>>>>>> >>>>>>> >>>>>>> >>>>>>> >>>>>>> >>>>>>> -- >>>>>>> Matt Sicker <boa...@gmail.com <mailto:boa...@gmail.com>> >>>>>> >>>>>> >>>>>> >>>>>> >>>>>> -- >>>>>> Matt Sicker <boa...@gmail.com <mailto:boa...@gmail.com>> >>>>> >>>> >>>> >>>> >>>> >>>> -- >>>> Matt Sicker <boa...@gmail.com <mailto:boa...@gmail.com>> >>>> >>>> >>>> >>>> -- >>>> Matt Sicker <boa...@gmail.com <mailto:boa...@gmail.com>> >>> >> >
