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.go...@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.po...@gmail.com >> <mailto:remko.po...@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.go...@dslextreme.com >> <mailto:ralph.go...@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 <boa...@gmail.com >>> <mailto:boa...@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.go...@dslextreme.com >>> <mailto:ralph.go...@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 <boa...@gmail.com >>>> <mailto:boa...@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.go...@dslextreme.com >>>> <mailto:ralph.go...@dslextreme.com>> wrote: >>>> Logback 1.2-SNAPSHOT >>>> >>>> Ralph >>>> >>>>> On Feb 6, 2017, at 8:29 PM, Remko Popma <remko.po...@gmail.com >>>>> <mailto:remko.po...@gmail.com>> wrote: >>>>> >>>>> Sorry what 1.2 do you mean? >>>>> >>>>> Sent from my iPhone >>>>> >>>>> On Feb 7, 2017, at 11:06, Apache <ralph.go...@dslextreme.com >>>>> <mailto:ralph.go...@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 <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>> >>>>>> >>>> >>>> >>>> >>>> >>>> -- >>>> Matt Sicker <boa...@gmail.com <mailto:boa...@gmail.com>> >>> >>> >>> >>> >>> -- >>> Matt Sicker <boa...@gmail.com <mailto:boa...@gmail.com>> >> >> >
