Return-Path: X-Original-To: archive-asf-public-internal@cust-asf2.ponee.io Delivered-To: archive-asf-public-internal@cust-asf2.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by cust-asf2.ponee.io (Postfix) with ESMTP id 8230D200C16 for ; Thu, 9 Feb 2017 13:22:31 +0100 (CET) Received: by cust-asf.ponee.io (Postfix) id 80BD0160B50; Thu, 9 Feb 2017 12:22:31 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id 33BE2160B4C for ; Thu, 9 Feb 2017 13:22:30 +0100 (CET) Received: (qmail 9016 invoked by uid 500); 9 Feb 2017 12:22:29 -0000 Mailing-List: contact log4j-dev-help@logging.apache.org; run by ezmlm Precedence: bulk List-Unsubscribe: List-Help: List-Post: List-Id: "Log4J Developers List" Reply-To: "Log4J Developers List" Delivered-To: mailing list log4j-dev@logging.apache.org Received: (qmail 8998 invoked by uid 99); 9 Feb 2017 12:22:29 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd3-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 09 Feb 2017 12:22:29 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd3-us-west.apache.org (ASF Mail Server at spamd3-us-west.apache.org) with ESMTP id EF5D8180028 for ; Thu, 9 Feb 2017 12:22:28 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd3-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: 1.302 X-Spam-Level: * X-Spam-Status: No, score=1.302 tagged_above=-999 required=6.31 tests=[HTML_MESSAGE=2, MIME_QP_LONG_LINE=0.001, RCVD_IN_DNSWL_LOW=-0.7, URIBL_BLOCKED=0.001] autolearn=disabled Received: from mx1-lw-eu.apache.org ([10.40.0.8]) by localhost (spamd3-us-west.apache.org [10.40.0.10]) (amavisd-new, port 10024) with ESMTP id 9B7dB3EJW2Ol for ; Thu, 9 Feb 2017 12:22:25 +0000 (UTC) Received: from smtp618.redcondor.net (smtp618.redcondor.net [208.80.206.18]) by mx1-lw-eu.apache.org (ASF Mail Server at mx1-lw-eu.apache.org) with ESMTPS id 73ABD5FC84 for ; Thu, 9 Feb 2017 12:22:24 +0000 (UTC) Received: from mailproxy10.neonova.net ([137.118.22.75]) by smtp618.redcondor.net ({25934d7d-0c4d-4838-a484-2a3cc0768185}) via TCP (outbound) with ESMTP id 20170209122211195_0618 for ; Thu, 09 Feb 2017 12:22:11 +0000 X-RC-FROM: X-RC-RCPT: Received: from [192.168.1.12] (ip72-201-73-113.ph.ph.cox.net [72.201.73.113]) (Authenticated sender: ralph.goers@dslextreme.com) by mailproxy10.neonova.net (Postfix) with ESMTPA id 87AA2360132 for ; Thu, 9 Feb 2017 07:22:07 -0500 (EST) From: Apache Content-Type: multipart/alternative; boundary=Apple-Mail-CD623AD8-5F51-46A6-82C2-9809AEF8586E Content-Transfer-Encoding: 7bit Mime-Version: 1.0 (1.0) Date: Thu, 9 Feb 2017 05:22:06 -0700 Subject: Re: Logback performance improvements Message-Id: <3F3DC7DE-B843-4B5D-AC56-7A49385F6354@dslextreme.com> References: <60624C7D-0CBA-46E6-AE86-018481DCDAF2@dslextreme.com> <9D9375FF-5EC1-4DC8-BB4A-0A867E29F3A0@dslextreme.com> <2693338C-1C0B-4DC5-8696-45114D3C3CBC@dslextreme.com> <91F75262-172A-40EE-919E-D873C32665BA@dslextreme.com> <399138BC-DD77-4338-B94D-BB1A043A6503@dslextreme.com> <5CD2D99E-E013-4EA7-A5E1-57FE78331202@dslextreme.com> <8C65696E-D243-4096-8BD6-3315707AE0DC@gmail.com> In-Reply-To: <8C65696E-D243-4096-8BD6-3315707AE0DC@gmail.com> To: Log4J Developers List X-Mailer: iPad Mail (14D27) X-DLP-OUTBOUND: 137.118.22.64/27 X-MAG-OUTBOUND: greymail.redcondor.net@137.118.22.64/27 archived-at: Thu, 09 Feb 2017 12:22:31 -0000 --Apple-Mail-CD623AD8-5F51-46A6-82C2-9809AEF8586E Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable 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 chan= ged and the test rerun. Ralph > On Feb 9, 2017, at 3:08 AM, Remko Popma wrote: >=20 > FYI, The write and flush methods in BufferedOutputStream are also synchron= ized, so we won't be able to do away with synchronization completely.=20 >=20 > In OutputStreamManager we synchronize multiple methods but these are neste= d calls. I thought reentrant synchronization had negligible overhead but I h= aven't measured this myself.=20 >=20 >=20 > Sent from my iPhone >=20 >> On Feb 9, 2017, at 2:31, Apache wrote: >>=20 >> I=E2=80=99m pretty sure the problem we have is that a) we are synchronizi= ng many methods and b) we are synchronizing more than just the write. Unfort= unately, I can=E2=80=99t figure out how to reduce that based on how disperse= d the code has gotten. >>=20 >> Ralph >>=20 >>> On Feb 8, 2017, at 10:14 AM, Apache wrote: >>>=20 >>> I tried to modify FileManager to just use a BufferedOutputStream but dis= covered I couldn=E2=80=99t as the layouts now require the ByteBuffer.=20 >>>=20 >>> Ralph >>>=20 >>>> On Feb 8, 2017, at 12:14 AM, Apache wrote:= >>>>=20 >>>> The append method isn=E2=80=99t synchronized but the writeBytes method a= cquires 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. >>>>=20 >>>> Ralph >>>>=20 >>>>> On Feb 6, 2017, at 5:23 PM, Matt Sicker wrote: >>>>>=20 >>>>> 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 synchroni= zed on the append method. >>>>>=20 >>>>> On 6 February 2017 at 18:18, Matt Sicker wrote: >>>>>> Is this something we can improve performance on by implementing a fil= e appender based on FileChannel or AsynchronousFileChannel instead of Output= Stream? >>>>>>=20 >>>>>>> On 6 February 2017 at 17:50, Apache wro= te: >>>>>>> Ceki has updated his numbers to include those reported on the mailin= g list. https://docs.google.com/spreadsheets/d/1cpb5D7qnyye4W0RTlHUnXedYK98c= atNZytYIu5D91m0/edit#gid=3D0 >>>>>>>=20 >>>>>>> I haven=E2=80=99t run the tests with Logback 1.2-SNAPSHOT but my num= bers for my two MacBooks are at https://docs.google.com/spreadsheets/d/1L67I= hmUVvyLBWtC6iq0TMj-j0vrbKsUKWuZV0Nlqisk/edit?usp=3Dsharing.=20 >>>>>>>=20 >>>>>>> Ralph >>>>>>>=20 >>>>>>>> On Feb 6, 2017, at 9:33 AM, Apache wro= te: >>>>>>>>=20 >>>>>>>> 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 framework= s. >>>>>>>>=20 >>>>>>>> Ralph >>>>>>>>=20 >>>>>>>>> On Feb 6, 2017, at 8:02 AM, Matt Sicker wrote: >>>>>>>>>=20 >>>>>>>>> This is all in a synchronous appender, right? Either way, that's r= ather interesting. >>>>>>>>>=20 >>>>>>>>> On 6 February 2017 at 07:54, Apache w= rote: >>>>>>>>>> Someone posted numbers on the Logback user=E2=80=99s list that ma= tch mine. It shows Logback 1.1.9 was pretty terrible, 1.1.10 is somewhat be= tter and 1.2-SNAPSHOT is on par or slightly better than Log4j 2. >>>>>>>>>>=20 >>>>>>>>>> Ralph >>>>>>>>>>=20 >>>>>>>>>>> On Feb 5, 2017, at 3:25 PM, Matt Sicker wrote= : >>>>>>>>>>>=20 >>>>>>>>>>> I think we need some comparisons on the log4j side: file appende= r 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 c= ool to see how these compose with async logging enabled in both log4j and lo= gback. >>>>>>>>>>>=20 >>>>>>>>>>> On 5 February 2017 at 16:06, Apache = wrote: >>>>>>>>>>>> You should run the code at https://github.com/ceki/logback-perf= to compare your results to Ceki=E2=80=99s. You also should capture the cpu= benchmark speed of your processor and get the speed of your hard drive. I us= ed Blackmagic speed test on my Mac. I am capturing my results in a Google sp= readsheet. I will post the like once I have it. >>>>>>>>>>>>=20 >>>>>>>>>>>> Ralph >>>>>>>>>>>>=20 >>>>>>>>>>>>> On Feb 5, 2017, at 1:48 PM, Gary Gregory wrote: >>>>>>>>>>>>>=20 >>>>>>>>>>>>> If you want, I can run tests on Windows once the build works o= n Windows again. >>>>>>>>>>>>>=20 >>>>>>>>>>>>> Let me know what args/command line... >>>>>>>>>>>>>=20 >>>>>>>>>>>>> Gary >>>>>>>>>>>>>=20 >>>>>>>>>>>>>> On Feb 5, 2017 11:58 AM, "Apache" wrote: >>>>>>>>>>>>>> I guess my MacBook Pro must fit in the Slow CPU/Fast Hard dri= ve category. With Logback 1.10 and -t 4 now get >>>>>>>>>>>>>>=20 >>>>>>>>>>>>>> Benchmark Mode Sampl= es Score Error Units >>>>>>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.julFile thrpt 2= 0 98187.673 =C2=B1 4935.712 ops/s >>>>>>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j1File thrpt 2= 0 842374.496 =C2=B1 6762.712 ops/s >>>>>>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2File thrpt 2= 0 1853062.583 =C2=B1 67032.225 ops/s >>>>>>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.log4j2RAF thrpt 2= 0 2036011.226 =C2=B1 53208.281 ops/s >>>>>>>>>>>>>> o.a.l.l.p.j.FileAppenderBenchmark.logbackFile thrpt 2= 0 999667.438 =C2=B1 12074.003 ops/s >>>>>>>>>>>>>>=20 >>>>>>>>>>>>>> I=E2=80=99ll have to try this on one my VMs at work. We don=E2= =80=99t run anything directly on bare metal any more. >>>>>>>>>>>>>>=20 >>>>>>>>>>>>>> Ralph >>>>>>>>>>>>>>=20 >>>>>>>>>>>>>>> On Feb 5, 2017, at 9:40 AM, Apache wrote: >>>>>>>>>>>>>>>=20 >>>>>>>>>>>>>>> Ceki finally fixed some of the performance problems in the Fi= leAppender. See https://logback.qos.ch/news.html and https://docs.google.com= /spreadsheets/d/1cpb5D7qnyye4W0RTlHUnXedYK98catNZytYIu5D91m0/edit#gid=3D0. I= suspect we have a few optimizations we can make. >>>>>>>>>>>>>>>=20 >>>>>>>>>>>>>>> Ralph >>>>>>>>>>>>>>=20 >>>>>>>>>>>>=20 >>>>>>>>>>>=20 >>>>>>>>>>>=20 >>>>>>>>>>>=20 >>>>>>>>>>> --=20 >>>>>>>>>>> Matt Sicker >>>>>>>>>>=20 >>>>>>>>>=20 >>>>>>>>>=20 >>>>>>>>>=20 >>>>>>>>> --=20 >>>>>>>>> Matt Sicker >>>>>>>>=20 >>>>>>>=20 >>>>>>=20 >>>>>>=20 >>>>>>=20 >>>>>> --=20 >>>>>> Matt Sicker >>>>>=20 >>>>>=20 >>>>>=20 >>>>> --=20 >>>>> Matt Sicker >>>>=20 >>>=20 >>=20 --Apple-Mail-CD623AD8-5F51-46A6-82C2-9809AEF8586E Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: quoted-printable
Ceki replied on twitter that the immed= iateFlush option is now a parameter of the appended, not the encoder, so it l= ooks 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 BufferedOutp= utStream are also synchronized, so we won't be able to do away with synchron= ization completely. 

In OutputStreamManager we= synchronize multiple methods but these are nested calls. I thought reentran= t 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=E2=80=99m pretty sure the problem we hav= e is that a) we are synchronizing many methods and b) we are synchronizing m= ore than just the write. Unfortunately, I can=E2=80=99t figure out how to re= duce that based on how dispersed the code has gotten.
<= br class=3D"">
Ralph

On Feb 8, 2017, at 10:14 AM, Apa= che <ralph.goers= @dslextreme.com> wrote:

=
I tried to modify FileManager to just use a BufferedOutputStream but discov= ered I couldn=E2=80=99t as the layouts now require the ByteBuffer. 

Ralph

On Fe= b 8, 2017, at 12:14 AM, Apache <ralph.goers@dslextreme.com> wrote:

The append method isn=E2=80=99t synchronized but= the writeBytes method acquires a lock. His code is actually a lot simpler t= han 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> wro= te:

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 <= span dir=3D"ltr" class=3D""><boards@gmail.com> wrote:
Is this something we c= an improve performance on by implementing a file appender based on FileChann= el 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. ht= tps://docs.google.com/spreadsheets/d/1cpb5D7qnyye4W0RTlHUnXedYK98catNZytYIu5D91m0/edit#gid=3D0
=

I haven=E2=80=99t run t= he 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=3Dsharing.&nbs= p;

Ralph

On Feb 6, 2017, at 9:33 AM, Apache <ralph.goers@dslextreme.com&g= t; wrote:

Yes, that is still the standard approach most peopl= e use and is the only way to provide a head-to-head comparison against the l= ogging frameworks.

Ralph

On Feb 6, 2017, at 8:02 AM, Matt Sicker <boards@gmail.com>= wrote:

This is all i= n a synchronous appender, right? Either way, that's rather interesting.

On 6 Fe= bruary 2017 at 07:54, Apache <ralph.goers@dsl= extreme.com> wrote:
Someone pos= ted numbers on the Logback user=E2=80=99s list that match mine.  It sho= ws Logback 1.1.9 was pretty terrible, 1.1.10 is somewhat better and 1.2-SNAP= SHOT 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 app= ender with 256k buffer size (which appears to be the default), and memory ma= pped 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/logback-perf to compare your results to Ceki=E2= =80=99s.  You also should capture the cpubenchmark speed of your proces= sor 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 lik= e once I have it.

= Ralph

On Feb 5, 2017, at 1:48 PM, Gary G= regory <garydgregory@gmail.com> wrote:

If you w= ant, 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 C= PU/Fast Hard drive category. With Logback 1.10 and -t 4  now get
<= div class=3D"">
Benchmark               &= nbsp;                     &= nbsp;   Mode  Samples        Score   &nbs= p;   Error  Units
o.a.l.l.p.j.FileAppenderBenchmark.julFile    &n= bsp;   thrpt       20    98187.673 =C2=B1 = ; 4935.712  ops/s
= o.a.l.l.p.j.FileAppenderBenchmark.log4j1File     t= hrpt       20   842374.496 =C2=B1  6762.712  o= ps/s
o.a.l.l.p.j.FileAppe= nderBenchmark.log4j2File     thrpt     &= nbsp; 20  1853062.583 =C2=B1 67032.225  ops/s
o.a.l.l.p.j.FileAppenderBenchmark.log4j2RAF      thrpt       20  203= 6011.226 =C2=B1 53208.281  ops/s
o.a.l.l.p.j.FileAppenderBenchmark.logbackFile=     thrpt       20   999667.438 =C2=B1 12074.0= 03  ops/s
I=E2=80=99= ll have to try this on one my VMs at work. We don=E2=80=99t run anything dir= ectly on bare metal any more.

Ralph

On Feb 5, 2017, at 9:40 AM, Apache <ralph.goers@d= slextreme.com> wrote:

Ceki finally fixed some of the performance problems in the = FileAppender. See https://logback.qos.ch/news.html&nbs= p;and htt= ps://docs.google.com/spreadsheets/d/1cpb5D7qnyye4W0RTlHUnXedYK98catNZytYIu5D91m0/edit#gid=3D0. I sus= pect we have a few optimizations we can make.

=
Ralph





=
--
Matt Sicker <boards@gmail.com>




=
--
Matt Sicker <boards@gmail.co= m>





--
Ma= tt Sicker <boards@gmail.com>


--
Matt Sicker <boards@gmail.com>



<= /div>= --Apple-Mail-CD623AD8-5F51-46A6-82C2-9809AEF8586E--