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 Wed, 08 Feb 2017 06:12:31 GMT
I used a ThreadLocal byte buffer and wrote to the file channel and if anything, it performed
slightly worse. This is probably because I had to write after ever event, not when the buffer
was full, otherwise the ordering of events in the output would get messed up.

I decided to throw the MemoryMappedFileAppender into the mix and I got some very strange behavior.
Using Logback 1.1.10 the overall results with 4 threads were:

Benchmark                                         Mode  Samples     Score     Error   Units
o.a.l.l.p.j.FileAppenderBenchmark.julFile        thrpt       10    98.886 ±  10.855  ops/ms
o.a.l.l.p.j.FileAppenderBenchmark.log4j1File     thrpt       10   826.640 ±  14.219  ops/ms
o.a.l.l.p.j.FileAppenderBenchmark.log4j2File     thrpt       10  1861.518 ± 139.885  ops/ms
o.a.l.l.p.j.FileAppenderBenchmark.log4j2MMF      thrpt       10  1478.489 ± 970.526  ops/ms
o.a.l.l.p.j.FileAppenderBenchmark.log4j2RAF      thrpt       10  2023.783 ±  41.284  ops/ms
o.a.l.l.p.j.FileAppenderBenchmark.logbackFile    thrpt       10   997.495 ±  42.801  ops/ms

What is strange is the actual output from the run for the MemoryMappedFileAppender. You will
notice that it starts off like a bat out of hell but then bogs down terribly. I’d love to
know why.

# VM invoker: /Library/Java/JavaVirtualMachines/jdk1.8.0_65.jdk/Contents/Home/jre/bin/java
# VM options: <none>
# Warmup: 10 iterations, 1 s each
# Measurement: 10 iterations, 1 s each
# Timeout: 10 min per iteration
# Threads: 4 threads, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Benchmark: org.apache.logging.log4j.perf.jmh.FileAppenderBenchmark.log4j2MMF

# Run progress: 50.00% complete, ETA 00:01:14
# Fork: 1 of 1
# Warmup Iteration   1: 2546.240 ops/ms
# Warmup Iteration   2: 3071.504 ops/ms
# Warmup Iteration   3: 2980.503 ops/ms
# Warmup Iteration   4: 2709.490 ops/ms
# Warmup Iteration   5: 2661.919 ops/ms
# Warmup Iteration   6: 2610.875 ops/ms
# Warmup Iteration   7: 2663.431 ops/ms
# Warmup Iteration   8: 2675.847 ops/ms
# Warmup Iteration   9: 2755.735 ops/ms
# Warmup Iteration  10: 2666.353 ops/ms
Iteration   1: 2577.419 ops/ms
Iteration   2: 2804.161 ops/ms
Iteration   3: 1179.059 ops/ms
Iteration   4: 1167.719 ops/ms
Iteration   5: 1170.686 ops/ms
Iteration   6: 1246.053 ops/ms
Iteration   7: 1173.593 ops/ms
Iteration   8: 1196.317 ops/ms
Iteration   9: 1127.199 ops/ms
Iteration  10: 1142.684 ops/ms

Ralph


> On Feb 7, 2017, at 10:55 AM, Apache <ralph.goers@dslextreme.com> wrote:
> 
> 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 <mailto: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