Is it possible that the memory mapped file starts resizing and remapping at this point?
Sent from my iPhone > On Feb 8, 2017, at 15:12, Apache <ralph.go...@dslextreme.com> wrote: > > 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> 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> 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> 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> 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> 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> wrote: >>>>>>>> Logback 1.2-SNAPSHOT >>>>>>>> >>>>>>>> Ralph >>>>>>>> >>>>>>>>> On Feb 6, 2017, at 8:29 PM, Remko Popma <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> 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> 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> >>>>>>>>>> >>>>>>>> >>>>>>> >>>>>>> >>>>>>> >>>>>>> -- >>>>>>> Matt Sicker <boa...@gmail.com> >>>>>> >>>>> >>>>> >>>>> >>>>> -- >>>>> Matt Sicker <boa...@gmail.com> >>>> >>> >> >
