logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Remko Popma <remko.po...@gmail.com>
Subject Re: Logback performance improvements
Date Thu, 09 Feb 2017 09:05:47 GMT
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.goers@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.goers@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.goers@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.goers@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 <boards@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 <boards@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.goers@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.goers@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 <boards@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.goers@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 <boards@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.goers@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
<garydgregory@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.goers@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.goers@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 <boards@gmail.com>
>>>>>>>>>> 
>>>>>>>>> 
>>>>>>>>> 
>>>>>>>>> 
>>>>>>>>> -- 
>>>>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>>> 
>>>>>>> 
>>>>>> 
>>>>>> 
>>>>>> 
>>>>>> -- 
>>>>>> Matt Sicker <boards@gmail.com>
>>>>> 
>>>>> 
>>>>> 
>>>>> -- 
>>>>> Matt Sicker <boards@gmail.com>
>>>> 
>>> 
>> 
> 

Mime
View raw message