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 Sun, 12 Feb 2017 14:54:20 GMT
#FriendsDontLetFriendsUseJavaUtilLogging

On Sun, Feb 12, 2017 at 11:41 PM, Remko Popma <remko.popma@gmail.com> wrote:

> But I agree it is interesting to see that a simple (RAF)FileAppender will
> outperform async logging if the sustained logging rate is faster than the
> appender can handle for long enough to fill up the queue. I've heard people
> in the high performance computing world mention this but I hadn't seen
> actual numbers until now.
>
> It is good to gain an intuition on these things. Async Loggers (with LMAX
> Disruptor) performance is worse than a plain File but not terrible either.
> Interesting how LogbackAsyncFile seems to suffer more than
> log4j2AsyncAppender.
>
> And yes, JUL is so bad it is not funny any more. We did document that
> <https://logging.apache.org/log4j/2.x/performance.html#fileLoggingComparison>
> but perhaps we need to evangelize it more...
>
>
> On Sun, Feb 12, 2017 at 4:59 PM, Remko Popma <remko.popma@gmail.com>
> wrote:
>
>> The queue is bigger but still fills up quickly because all the benchmarks
>> do is add events as quickly as possible and the FileAppender can't keep up
>> with that rate.
>>
>> Sent from my iPhone
>>
>> On Feb 12, 2017, at 16:19, Apache <ralph.goers@dslextreme.com> wrote:
>>
>> I added the tests so you guys could run them and take a look. I have no
>> problem with the changes being reverted.
>>
>> As I think I said, I expected most of the async appenders to back up. I
>> expected them to be a bit slower, but I didn’t expect them to be as slow as
>> they are when the queue is full. I also don’t understand why AsyncLogger is
>> slower as it should have a large ring buffer if I understand correctly.
>>
>> Ralph
>>
>> On Feb 11, 2017, at 4:36 PM, Remko Popma <remko.popma@gmail.com> wrote:
>>
>> I don't think it is a good idea to mix async tests with sync tests.
>>
>> We already have separate benchmarks for the various ways to log
>> asynchronously, if you want to compare them just run those also.
>>
>> JMH makes it super easy to build benchmarks but we have to be very
>> careful that the test really measures what we want to measure.
>>
>> Asynchronous logging has two "states", queue full and space available. Do
>> we want to measure the queue full state or the space available state (or
>> the transition between the two)?
>>
>> With a normal FileAppender JMH will iterate so fast that the queue
>> immediately fills up. This will likely happen during the warmup iterations
>> (no guarantee of course).
>>
>> What actually happens in that state? We used to block until space becomes
>> available in the queue. What we do now depends on the configured
>> AsyncQueueFullPolicy. Because blocking caused deadlocks in some scenarios,
>> our current default is to bypass the queue and log to the FileAppender
>> directly. I expect that to be slower than the simple FileAppender because
>> of the additional lock contention on the tail of the queue during the
>> attempted thread handover.
>>
>> The "queue full" state is not the normal logging state for an
>> application. If we want to measure this we should move these tests to a
>> separate benchmark that is clearly marked "QueueFullAsyncBenchmark" or
>> something like that.
>> Otherwise people reading these benchmark results will misinterpret them
>> and get confused.
>>
>> The existing Async benchmarks ensure they measure the "queue space
>> available" state.
>>
>> Remko
>>
>> Sent from my iPhone
>>
>> On Feb 12, 2017, at 4:37, Apache <ralph.goers@dslextreme.com> wrote:
>>
>> Just for fun I decided to add some more tests to the file appender
>> benchmark. I’ve checked them in. Please review them to see if everything is
>> configured so the tests make sense.
>>
>> Note that I would expect the async appenders to reduce to the speed of
>> the file appender, since once the queue fills up that is what they are
>> waiting on. But I didn’t set a buffer size for the disruptor or async
>> logger tests so I would have expected those to be quite a bit faster than
>> the regular file test.
>>
>> The one thing that is definitely worth noting is how truly terrible the
>> JUL file appender is. I have to assume that it must be doing an immediate
>> flush on every write.
>>
>> This is on my MacBook Pro - what Ceki would call Fast CPU/Fast SSD
>>
>> Benchmark                                                  Mode  Samples
>>     Score     Error   Units
>> o.a.l.l.p.j.FileAppenderBenchmark.julFile                 thrpt
>> 10    69.546 ±   2.635  ops/ms
>> o.a.l.l.p.j.FileAppenderBenchmark.log4j1File              thrpt       10
>>   783.006 ±  28.138  ops/ms
>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2AsyncAppender     thrpt       10
>>   939.605 ±  38.655  ops/ms
>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2AsyncDisruptor    thrpt
>> 10  1446.522 ±  45.485  ops/ms
>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2AsyncLogger       thrpt
>> 10  1269.014 ±  27.236  ops/ms
>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2File              thrpt
>> 10  1475.605 ±  74.675  ops/ms
>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2MMF               thrpt
>> 10  2131.240 ± 114.184  ops/ms
>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2RAF               thrpt
>> 10  1499.667 ±  39.668  ops/ms
>> o.a.l.l.p.j.FileAppenderBenchmark.logbackAsyncFile        thrpt       10
>>   326.969 ±   2.690  ops/ms
>> o.a.l.l.p.j.FileAppenderBenchmark.logbackFile             thrpt       10
>>   940.527 ±  34.090  ops/ms
>>
>> And this is on my old MacBook Pro - it uses a hard drive so isn’t very
>> fast.
>>
>> Benchmark                                                  Mode  Samples
>>     Score     Error   Units
>> o.a.l.l.p.j.FileAppenderBenchmark.julFile                 thrpt       10
>>    15.722 ±  15.557  ops/ms
>> o.a.l.l.p.j.FileAppenderBenchmark.log4j1File              thrpt       10
>>   530.668 ±  54.193  ops/ms
>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2AsyncAppender     thrpt       10
>>   498.620 ± 178.693  ops/ms
>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2AsyncDisruptor    thrpt       10
>>   454.541 ± 145.505  ops/ms
>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2AsyncLogger       thrpt       10
>>   527.784 ± 150.269  ops/ms
>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2File              thrpt       10
>>   587.605 ±  97.769  ops/ms
>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2MMF               thrpt       10
>>  1966.092 ± 431.196  ops/ms
>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2RAF               thrpt       10
>>   364.694 ±  34.602  ops/ms
>> o.a.l.l.p.j.FileAppenderBenchmark.logbackAsyncFile        thrpt       10
>>   258.220 ±   1.936  ops/ms
>> o.a.l.l.p.j.FileAppenderBenchmark.logbackFile             thrpt       10
>>   560.958 ±  36.982  ops/ms
>>
>> Ralph
>>
>> On Feb 9, 2017, at 1:39 PM, Matt Sicker <boards@gmail.com> wrote:
>>
>> Also, there are some potential issues with logback-perf:
>>
>> * JMH is way out of date (1.11.3 versus 1.17.4)
>> * Less warmup iterations than we do
>>
>> Anyways, results for 32 threads (8 core environment):
>>
>> Benchmark                           Mode  Cnt     Score    Error   Units
>> FileAppenderBenchmark.log4j1File   thrpt   10   695.774 ±  9.567  ops/ms
>> FileAppenderBenchmark.log4j2File   thrpt   10  1300.091 ± 17.579  ops/ms
>> FileAppenderBenchmark.log4j2RAF    thrpt   10  1365.118 ± 17.656  ops/ms
>> FileAppenderBenchmark.logbackFile  thrpt   10   766.294 ± 10.121  ops/ms
>>
>> On 9 February 2017 at 14:37, Matt Sicker <boards@gmail.com> wrote:
>>
>>> That value does look messed up. I'll re-run the 32 thread tests. Also,
>>> I'm not on the logback lists yet, so I'll sign up this afternoon.
>>>
>>> On 9 February 2017 at 14:35, Apache <ralph.goers@dslextreme.com> wrote:
>>>
>>>> What is up with that score for 32 threads?  That can’t possibly be
>>>> correct.
>>>>
>>>> Ralph
>>>>
>>>> On Feb 9, 2017, at 12:45 PM, Matt Sicker <boards@gmail.com> wrote:
>>>>
>>>> I ran the logback-perf repo on the same AWS instance. Here's the CSV
>>>> data. It appears as soon as more than one thread comes into play, log4j2
>>>> has better scores.
>>>>
>>>> "Benchmark","Mode","Threads","Samples","Score","Score Error
>>>> (99.9%)","Unit"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j1File","thrp
>>>> t",1,10,964.600470,279.139021,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j2File","thrp
>>>> t",1,10,1274.682156,6.179197,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j2RAF","thrpt
>>>> ",1,10,1257.026405,32.898682,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.logbackFile","thr
>>>> pt",1,10,1363.683525,41.884725,"ops/ms"
>>>> "Benchmark","Mode","Threads","Samples","Score","Score Error
>>>> (99.9%)","Unit"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j1File","thrp
>>>> t",2,10,687.304803,13.266922,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j2File","thrp
>>>> t",2,10,1386.596198,207.305249,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j2RAF","thrpt
>>>> ",2,10,1579.884762,24.098318,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.logbackFile","thr
>>>> pt",2,10,953.138212,99.156775,"ops/ms"
>>>> "Benchmark","Mode","Threads","Samples","Score","Score Error
>>>> (99.9%)","Unit"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j1File","thrp
>>>> t",4,10,670.442970,15.049614,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j2File","thrp
>>>> t",4,10,1218.543593,18.234077,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j2RAF","thrpt
>>>> ",4,10,1309.092881,31.547936,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.logbackFile","thr
>>>> pt",4,10,845.168355,24.547390,"ops/ms"
>>>> "Benchmark","Mode","Threads","Samples","Score","Score Error
>>>> (99.9%)","Unit"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j1File","thrp
>>>> t",8,10,689.805339,7.415023,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j2File","thrp
>>>> t",8,10,1196.396592,19.360776,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j2RAF","thrpt
>>>> ",8,10,1319.477318,10.601260,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.logbackFile","thr
>>>> pt",8,10,816.608726,25.603234,"ops/ms"
>>>> "Benchmark","Mode","Threads","Samples","Score","Score Error
>>>> (99.9%)","Unit"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j1File","thrp
>>>> t",16,10,687.623660,16.114008,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j2File","thrp
>>>> t",16,10,1203.649145,8.835115,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j2RAF","thrpt
>>>> ",16,10,1266.241778,7.564414,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.logbackFile","thr
>>>> pt",16,10,789.507183,9.866592,"ops/ms"
>>>> "Benchmark","Mode","Threads","Samples","Score","Score Error
>>>> (99.9%)","Unit"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j1File","thrp
>>>> t",32,10,690.252411,11.587858,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j2File","thrp
>>>> t",32,10,1514185.478492,126804.168771,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j2RAF","thrpt
>>>> ",32,10,1264.049209,28.309088,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.logbackFile","thr
>>>> pt",32,10,754.828687,14.865909,"ops/ms"
>>>> "Benchmark","Mode","Threads","Samples","Score","Score Error
>>>> (99.9%)","Unit"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j1File","thrp
>>>> t",64,10,670.498518,11.147198,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j2File","thrp
>>>> t",64,10,1293.301940,22.687086,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.log4j2RAF","thrpt
>>>> ",64,10,1380.527892,14.907542,"ops/ms"
>>>> "ch.qos.logback.perf.FileAppenderBenchmark.logbackFile","thr
>>>> pt",64,10,750.528159,11.356281,"ops/ms"
>>>>
>>>> On 9 February 2017 at 13:02, Apache <ralph.goers@dslextreme.com> wrote:
>>>>
>>>>> You might try running Ceki’s benchmark project on AWS and publish
>>>>> those numbers here. He also asked people to publish numbers on the Logback
>>>>> user’s list so he can add them to his spreadsheet.
>>>>>
>>>>> From your numbers and the numbers I’ve been getting, it is clear to
me
>>>>> that the SSDs in Apple’s MacBook’s are pretty awesome. From the hardware
>>>>> Remko is listing I’d say his machine is about as old as my other MacBook
>>>>> except that he has an SSD that is slightly faster than my hard drive.
>>>>>
>>>>> Ralph
>>>>>
>>>>> On Feb 9, 2017, at 11:12 AM, Matt Sicker <boards@gmail.com> wrote:
>>>>>
>>>>> Ran on an AWS instance (CentOS 7.2), cpuinfo says 8-core Intel(R)
>>>>> Xeon(R) CPU E5-2666 v3 @ 2.90GHz, not super sure about all the params
>>>>> involved in making the instance, but here's some data (same strangeness
>>>>> with MMF):
>>>>>
>>>>> Benchmark                                         Mode  Samples
>>>>> Score     Error   Units
>>>>> o.a.l.l.p.j.FileAppenderBenchmark.julFile        thrpt       10
>>>>>  86.867 ±   4.502  ops/ms
>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j1File     thrpt       10
>>>>> 671.156 ±   7.099  ops/ms
>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2File     thrpt       10
>>>>>  1221.814 ±  22.130  ops/ms
>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2MMF      thrpt       10
>>>>>  1178.407 ± 960.141  ops/ms
>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2RAF      thrpt       10
>>>>>  1220.746 ±  34.421  ops/ms
>>>>> o.a.l.l.p.j.FileAppenderBenchmark.logbackFile    thrpt       10
>>>>> 898.122 ±   8.128  ops/ms
>>>>>
>>>>> On 9 February 2017 at 12:02, Matt Sicker <boards@gmail.com> wrote:
>>>>>
>>>>>> Run on a MacBook Pro (Retina, 15-inch, Mid 2015) 2.5 GHz Intel Core
>>>>>> i7. Can find out more hardware specs if needed. I also noticed that
the
>>>>>> memory mapped file starts out fast and slows down over time (somewhat
seen
>>>>>> by the error value here).
>>>>>>
>>>>>> Benchmark                                         Mode  Samples
>>>>>> Score     Error   Units
>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.julFile        thrpt       10
>>>>>>  96.540 ±   7.875  ops/ms
>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j1File     thrpt       10
>>>>>> 766.286 ±  11.461  ops/ms
>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2File     thrpt       10
>>>>>>  1787.620 ±  36.695  ops/ms
>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2MMF      thrpt       10
>>>>>>  1506.588 ± 956.354  ops/ms
>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2RAF      thrpt       10
>>>>>>  1934.966 ±  50.089  ops/ms
>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.logbackFile    thrpt       10
>>>>>>  1285.066 ±  12.674  ops/ms
>>>>>>
>>>>>> On 9 February 2017 at 11:44, Remko Popma <remko.popma@gmail.com>
>>>>>> wrote:
>>>>>>
>>>>>>> My results on Windows 10 64-bit laptop (java 1.8.0_51 64bit),
>>>>>>> i5-3317u CPU @ 1.70GHz (dual core with hyperthreading for 4 virtual
cores),
>>>>>>> SSD hard disk:
>>>>>>>
>>>>>>> java -jar log4j-perf/target/benchmarks.jar
>>>>>>> ".*FileAppenderBenchmark.*" -f 1 -wi 10 -i 20 -t 4 -tu ms
>>>>>>>
>>>>>>> # Run complete. Total time: 00:03:58
>>>>>>>
>>>>>>> Benchmark                                         Mode  Samples
>>>>>>> Score     Error   Units
>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.julFile        thrpt      
20
>>>>>>>  37.646 ±   0.876  ops/ms
>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j1File     thrpt      
20
>>>>>>> 405.305 ±   6.596  ops/ms
>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2File     thrpt      
20
>>>>>>> 751.949 ±  16.055  ops/ms
>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2MMF      thrpt      
20
>>>>>>>  1250.666 ± 168.757  ops/ms
>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2RAF      thrpt      
20
>>>>>>> 728.743 ±  23.909  ops/ms
>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.logbackFile    thrpt      
20
>>>>>>> 676.926 ±  19.518  ops/ms
>>>>>>>
>>>>>>> --------------------
>>>>>>> Logback config without immediateFlush=false:
>>>>>>>
>>>>>>> # Run complete. Total time: 00:03:44
>>>>>>>
>>>>>>> Benchmark                                         Mode  Samples
>>>>>>> Score     Error   Units
>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.julFile        thrpt      
20
>>>>>>>  37.949 ±   1.220  ops/ms
>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j1File     thrpt      
20
>>>>>>> 404.042 ±   8.450  ops/ms
>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2File     thrpt      
20
>>>>>>> 690.393 ± 115.537  ops/ms
>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2MMF      thrpt      
20
>>>>>>>  1221.681 ±  82.205  ops/ms
>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2RAF      thrpt      
20
>>>>>>> 823.059 ±  41.512  ops/ms
>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.logbackFile    thrpt      
20
>>>>>>>  83.352 ±  11.911  ops/ms
>>>>>>>
>>>>>>>
>>>>>>> On Fri, Feb 10, 2017 at 1:05 AM, Mikael Ståldal <
>>>>>>> mikael.staldal@magine.com> wrote:
>>>>>>>
>>>>>>>> I guess that with a memory mapped file, you leave it to the
OS to
>>>>>>>> do the best it can, and you lose any direct control over
how it is actually
>>>>>>>> done.
>>>>>>>>
>>>>>>>> On Thu, Feb 9, 2017 at 4:52 PM, Apache <ralph.goers@dslextreme.com>
>>>>>>>> wrote:
>>>>>>>>
>>>>>>>>> On my Mac Pro with the slower external SSD I now got:
>>>>>>>>>
>>>>>>>>> Benchmark                                         Mode
 Samples
>>>>>>>>>   Score     Error   Units
>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.julFile        thrpt
      10
>>>>>>>>>   73.739 ±   0.740  ops/ms
>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j1File     thrpt
      10
>>>>>>>>> 683.129 ±   9.407  ops/ms
>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2File     thrpt
      10
>>>>>>>>> 991.293 ± 193.049  ops/ms
>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2MMF      thrpt
      10
>>>>>>>>> 3072.250 ±  63.475  ops/ms
>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2RAF      thrpt
      10
>>>>>>>>> 1056.256 ± 137.673  ops/ms
>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.logbackFile    thrpt
      10
>>>>>>>>> 784.723 ± 153.226  ops/ms
>>>>>>>>>
>>>>>>>>> and on the same machine with the faster internal SSD
I got:
>>>>>>>>>
>>>>>>>>> Benchmark                                         Mode
 Samples
>>>>>>>>>   Score     Error   Units
>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.julFile        thrpt
      10
>>>>>>>>>   74.661 ±   0.232  ops/ms
>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j1File     thrpt
      10
>>>>>>>>> 647.041 ±   2.994  ops/ms
>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2File     thrpt
      10
>>>>>>>>> 1333.887 ±  13.921  ops/ms
>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2MMF      thrpt
      10
>>>>>>>>> 3025.726 ± 210.414  ops/ms
>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2RAF      thrpt
      10
>>>>>>>>> 1433.620 ±  11.194  ops/ms
>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.logbackFile    thrpt
      10
>>>>>>>>> 1026.319 ±  13.347  ops/ms
>>>>>>>>>
>>>>>>>>> I will continue to run this on a few other configurations.
I think
>>>>>>>>> I would also like to add the async appenders/loggers
to this test so that
>>>>>>>>> one can see all the various options.
>>>>>>>>>
>>>>>>>>> It is really quite interesting to me to see how the memory
mapped
>>>>>>>>> appender behaves so differently from one machine to another.
I don’t know
>>>>>>>>> under what circumstances I would recommend using it though.
>>>>>>>>>
>>>>>>>>> Ralph
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> On Feb 9, 2017, at 7:03 AM, Apache <ralph.goers@dslextreme.com>
>>>>>>>>> wrote:
>>>>>>>>>
>>>>>>>>> After modifying the configuration the new results on
my laptop are:
>>>>>>>>>
>>>>>>>>> Benchmark                                         Mode
 Samples
>>>>>>>>>   Score      Error   Units
>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.julFile        thrpt
      10
>>>>>>>>>   92.580 ±    3.698  ops/ms
>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j1File     thrpt
      10
>>>>>>>>> 828.707 ±   55.006  ops/ms
>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2File     thrpt
      10
>>>>>>>>> 1647.230 ±  125.682  ops/ms
>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2MMF      thrpt
      10
>>>>>>>>> 1465.002 ± 1284.943  ops/ms
>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2RAF      thrpt
      10
>>>>>>>>> 1765.340 ±  149.707  ops/ms
>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.logbackFile    thrpt
      10
>>>>>>>>> 1192.594 ±   57.777  ops/ms
>>>>>>>>>
>>>>>>>>> I will try the other machines later and post those results.
>>>>>>>>>
>>>>>>>>> Ralph
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> On Feb 9, 2017, at 5:22 AM, Apache <ralph.goers@dslextreme.com>
>>>>>>>>> wrote:
>>>>>>>>>
>>>>>>>>> Ceki replied on twitter that the immediateFlush option
is now a
>>>>>>>>> parameter of the appended, not the encoder, so it looks
like the confit
>>>>>>>>> needs to be changed and the test rerun.
>>>>>>>>>
>>>>>>>>> Ralph
>>>>>>>>>
>>>>>>>>> On Feb 9, 2017, at 3:08 AM, Remko Popma <remko.popma@gmail.com>
>>>>>>>>> wrote:
>>>>>>>>>
>>>>>>>>> FYI, The write and flush methods in BufferedOutputStream
are also
>>>>>>>>> synchronized, so we won't be able to do away with synchronization
>>>>>>>>> completely.
>>>>>>>>>
>>>>>>>>> In OutputStreamManager we synchronize multiple methods
but these
>>>>>>>>> are nested calls. I thought reentrant synchronization
had negligible
>>>>>>>>> overhead but I haven't measured this myself.
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> Sent from my iPhone
>>>>>>>>>
>>>>>>>>> On Feb 9, 2017, at 2:31, 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/spread
>>>>>>>>>>> sheets/d/1L67IhmUVvyLBWtC6iq0TMj-j0vrbKsUKWuZV0Nlqisk/edit?u
>>>>>>>>>>> sp=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/logbac
>>>>>>>>>>>>> k-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/1cpb5D7qny
>>>>>>>>>>>>>> ye4W0RTlHUnXedYK98catNZytYIu5D91m0/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>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> --
>>>>>>>>
>>>>>>>>
>>>>>>>> *Mikael Ståldal*
>>>>>>>> Senior software developer
>>>>>>>>
>>>>>>>> *Magine TV*
>>>>>>>> mikael.staldal@magine.com
>>>>>>>> Grev Turegatan 3  | 114 46 Stockholm, Sweden  |   www.magine.com
>>>>>>>>
>>>>>>>> Privileged and/or Confidential Information may be contained
in this
>>>>>>>> message. If you are not the addressee indicated in this message
>>>>>>>> (or responsible for delivery of the message to such a person),
you
>>>>>>>> may not copy or deliver this message to anyone. In such case,
>>>>>>>> you should destroy this message and kindly notify the sender
by
>>>>>>>> reply email.
>>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>
>>>>>>
>>>>>> --
>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>
>>>>>
>>>>>
>>>>>
>>>>> --
>>>>> Matt Sicker <boards@gmail.com>
>>>>>
>>>>>
>>>>>
>>>>
>>>>
>>>> --
>>>> Matt Sicker <boards@gmail.com>
>>>>
>>>>
>>>>
>>>
>>>
>>> --
>>> Matt Sicker <boards@gmail.com>
>>>
>>
>>
>>
>> --
>> Matt Sicker <boards@gmail.com>
>>
>>
>>
>>
>

Mime
View raw message