logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Apache <ralph.go...@dslextreme.com>
Subject Re: Logback performance improvements
Date Tue, 07 Feb 2017 17:55:23 GMT
True, but I would still like to also see what difference it makes using the FileChannel instead
of the OutputStream.

Ralph

> On Feb 7, 2017, at 9:45 AM, Remko Popma <remko.popma@gmail.com> wrote:
> 
> That is all doable but it may be a good idea to test if that is really where the bottleneck
is. 
> We could try whether we get better numbers if we remove the current synchronization (ignoring
any scrambled output, just for testing purposes).
> 
> 
> On Wed, Feb 8, 2017 at 1:40 AM, Apache <ralph.goers@dslextreme.com <mailto:ralph.goers@dslextreme.com>>
wrote:
> In looking at FileManager and OutputStreamManager it does have a ByteBuffer but it requires
synchronization. I am thinking it might make more sense to have a ThreadLocal ByteBuffer and
then pass that to FileChannel.write() so that no synchronization is required.
> 
> Ralph
> 
>> On Feb 7, 2017, at 9:36 AM, Matt Sicker <boards@gmail.com <mailto:boards@gmail.com>>
wrote:
>> 
>> Can't we use the ByteBuffers introduced in the GC-free epic? I was under the impression
that byte arrays being passed to appenders was created from a ByteBuffer at this point, though
I haven't really taken a close look at this.
>> 
>> On 7 February 2017 at 10:05, Apache <ralph.goers@dslextreme.com <mailto:ralph.goers@dslextreme.com>>
wrote:
>> A FileChannel is guaranteed to be thread safe. You can obtain a FileChannel from
a FlieOutputStream, so that would seem to imply that FileOutputStream might be thread-safe,
but you can’t really know that without looking at the source. The problem is that FileChannel.write()
takes a ByteBuffer whereas FileOutputStream.write() accepts a byte array. To be thread safe
it would have to safely copy the byte array into the byte buffer to pass to the FileChannel.
But FileOutputStream doesn’t use the FileChannel at all in Java 7. It calls a native method
that doesn’t specify whether it is thread-safe or not, so simply removing the synchronization
isn’t guaranteed to work properly. 
>> 
>> OTOH, RandomAccessFile doesn’t say that it is thread-safe either and we are not
synchronizing writes to it.
>> 
>> Ralph
>> 
>>> On Feb 7, 2017, at 8:37 AM, Matt Sicker <boards@gmail.com <mailto:boards@gmail.com>>
wrote:
>>> 
>>> I looked at 1.2-SNAPSHOT and 1.1.10 and saw nothing special other than a lack
of a synchronized keyword on the equivalent append method. Perhaps he figured out a simpler
way to emulate locking?
>>> 
>>> I've been working with async/non-blocking streaming APIs for long enough now
that I can't even remember the last time I had to write an actual lock.
>>> 
>>> On 6 February 2017 at 22:02, Apache <ralph.goers@dslextreme.com <mailto:ralph.goers@dslextreme.com>>
wrote:
>>> Logback 1.2-SNAPSHOT
>>> 
>>> Ralph
>>> 
>>>> On Feb 6, 2017, at 8:29 PM, Remko Popma <remko.popma@gmail.com <mailto:remko.popma@gmail.com>>
wrote:
>>>> 
>>>> Sorry what 1.2 do you mean? 
>>>> 
>>>> Sent from my iPhone
>>>> 
>>>> On Feb 7, 2017, at 11:06, Apache <ralph.goers@dslextreme.com <mailto:ralph.goers@dslextreme.com>>
wrote:
>>>> 
>>>>> In 1.2?  That may work for a FileOutputStream but it isn’t guaranteed
to work for others.
>>>>> 
>>>>> Ralph
>>>>> 
>>>>>> On Feb 6, 2017, at 5:23 PM, Matt Sicker <boards@gmail.com <mailto: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 <mailto: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
<mailto: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
<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.goers@dslextreme.com
<mailto: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
<mailto: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
<mailto: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
<mailto: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
<mailto:ralph.goers@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 <garydgregory@gmail.com
<mailto: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
<mailto: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
<mailto:ralph.goers@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 <boards@gmail.com <mailto:boards@gmail.com>>
>>>>>>>> 
>>>>>>>> 
>>>>>>>> 
>>>>>>>> 
>>>>>>>> -- 
>>>>>>>> Matt Sicker <boards@gmail.com <mailto:boards@gmail.com>>
>>>>>>> 
>>>>>> 
>>>>>> 
>>>>>> 
>>>>>> 
>>>>>> -- 
>>>>>> Matt Sicker <boards@gmail.com <mailto:boards@gmail.com>>
>>>>>> 
>>>>>> 
>>>>>> 
>>>>>> -- 
>>>>>> Matt Sicker <boards@gmail.com <mailto:boards@gmail.com>>
>>>>> 
>>> 
>>> 
>>> 
>>> 
>>> -- 
>>> Matt Sicker <boards@gmail.com <mailto:boards@gmail.com>>
>> 
>> 
>> 
>> 
>> -- 
>> Matt Sicker <boards@gmail.com <mailto:boards@gmail.com>>
> 
> 


Mime
View raw message