I will try taking a look when I get home from work tonight. Ceki reported some strange numbers about Log4j 1 outperforming Log4j2 before, and when we showed results from 3 or 4 environments that disproved his claims, he never really explained how that happened.
Not sure if there's some issue with his test setup... I would definitely double check his numbers. Sent from my iPhone > On Feb 9, 2017, at 14:12, Apache <ralph.go...@dslextreme.com> wrote: > > 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> 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> 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> 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> 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> wrote: >>>>>>> Ceki has updated his numbers to include those reported on the mailing >>>>>>> list. >>>>>>> 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. >>>>>>> >>>>>>> >>>>>>> Ralph >>>>>>> >>>>>>>> On Feb 6, 2017, at 9:33 AM, Apache <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> 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> >>>>>>>>> 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> 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> >>>>>>>>>>> wrote: >>>>>>>>>>>> You should run the code at 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> >>>>>>>>>>>>> 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> >>>>>>>>>>>>>> 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> >>>>>>>>>>>>>>> wrote: >>>>>>>>>>>>>>> >>>>>>>>>>>>>>> Ceki finally fixed some of the performance problems in the >>>>>>>>>>>>>>> FileAppender. See https://logback.qos.ch/news.html and >>>>>>>>>>>>>>> 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> >>>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>>> -- >>>>>>>>> Matt Sicker <boa...@gmail.com> >>>>>>>> >>>>>>> >>>>>> >>>>>> >>>>>> >>>>>> -- >>>>>> Matt Sicker <boa...@gmail.com> >>>>> >>>>> >>>>> >>>>> -- >>>>> Matt Sicker <boa...@gmail.com> >>>> >>> >> >
