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: Fast and Furious
Date Tue, 01 Mar 2016 22:10:13 GMT
Notes on SimplePerfTest: if you have too many iterations on the producer
side (the test app) the ring buffer fills up and starts blocking until
space is available, reducing speed to synchronous logging or worse. Same if
we don't wait between tests to give the background thread a chance to drain
the buffer.

I haven't done enough analysis yet on changes since 2.0. Rough overview:
- call Message.getFormattedMessage() before enqueueing to ensure current
param values are captured
- added nanoTime to event, initialize before enqueueing
- big change to support restarting web apps: encapsulate Disruptor in
separate helper class rather than static field in AsyncLogger, structure of
data in ThreadLocal changed, Thread name cached in separate ThreadLocal.

However, undoing all these changes in AsyncLogger at first gave me the
original performance again, but doing the same again in a separate
workspace I don't get that level of throughput anymore. Not sure what I did
wrong (or was my first result a fluke?)

Hope this helps...


On Wednesday, 2 March 2016, Remko Popma <remko.popma@gmail.com> wrote:

> In the same directory as SimplePerfTest is a Windows batch file. This is
> what I use to run it.
>
> Sent from my iPhone
>
> On 2016/03/02, at 6:03, Matt Sicker <boards@gmail.com
> <javascript:_e(%7B%7D,'cvml','boards@gmail.com');>> wrote:
>
> SimplePerfTest is a main method class. But that plugin looks pretty sweet,
> I'll check it out anyways.
>
> On 1 March 2016 at 14:47, Gary Gregory <garydgregory@gmail.com
> <javascript:_e(%7B%7D,'cvml','garydgregory@gmail.com');>> wrote:
>
>> Maybe this would help: https://github.com/artyushov/idea-jmh-plugin ?
>>
>> Gary
>>
>> On Tue, Mar 1, 2016 at 12:43 PM, Matt Sicker <boards@gmail.com
>> <javascript:_e(%7B%7D,'cvml','boards@gmail.com');>> wrote:
>>
>>> I can't even figure out how to execute the simple perf test class.
>>> IntelliJ gives me some annotation processing error, and doing it from the
>>> command line is turning into a classpath nightmare to figure out what jars
>>> are needed to execute the test manually.
>>>
>>> On 1 March 2016 at 11:34, Gary Gregory <garydgregory@gmail.com
>>> <javascript:_e(%7B%7D,'cvml','garydgregory@gmail.com');>> wrote:
>>>
>>>> Before the talk: Hi, I'm Remko, I help on Apache Log4j, are you
>>>> available after the preso to talk about some issue we are seeing?
>>>>
>>>> Gary
>>>> On Mar 1, 2016 8:29 AM, "Matt Sicker" <boards@gmail.com
>>>> <javascript:_e(%7B%7D,'cvml','boards@gmail.com');>> wrote:
>>>>
>>>>> I'm attending a JUG meetup tonight with Kirk Pepperdine presenting.
>>>>> It's supposed to be a Java performance workshop type of thing, so if
you've
>>>>> got a decent way to ask about it, I could see if he can help figure out
>>>>> this regression. I can at least show off the SimplePerfTest and any
>>>>> microbenchmarks we have.
>>>>>
>>>>> On 28 February 2016 at 11:54, Matt Sicker <boards@gmail.com
>>>>> <javascript:_e(%7B%7D,'cvml','boards@gmail.com');>> wrote:
>>>>>
>>>>>> Take a look at the git bisect command. Might help you find which
>>>>>> changes caused the problem.
>>>>>>
>>>>>>
>>>>>> On Sunday, 28 February 2016, Gary Gregory <garydgregory@gmail.com
>>>>>> <javascript:_e(%7B%7D,'cvml','garydgregory@gmail.com');>>
wrote:
>>>>>>
>>>>>>> Thank you for digging in Remko. This is will be a nice theme
to
>>>>>>> publicize when you get it figured out.
>>>>>>>
>>>>>>> Gary
>>>>>>> On Feb 28, 2016 4:08 AM, "Remko Popma" <remko.popma@gmail.com>
>>>>>>> wrote:
>>>>>>>
>>>>>>>> After removing the potential impact of appenders and layouts
by
>>>>>>>> testing with log4j-core\src\test\resources\perf-CountingNoOpAppender.xml
>>>>>>>> and org.apache.logging.log4j.core.async.perftest.SimplePerfTest,
I've
>>>>>>>> confirmed my initial numbers:
>>>>>>>>
>>>>>>>> 2.0: 7.5M ops/sec
>>>>>>>> 2.1: 6M ops/sec
>>>>>>>> 2.2: 6M ops/sec
>>>>>>>> 2.3: 6M ops/sec
>>>>>>>> 2.4: 4.5M ops/sec
>>>>>>>> 2.5: 4M ops/sec
>>>>>>>> 2.6: 2M ops/sec
>>>>>>>>
>>>>>>>> I tried reverting various changes made to AsyncLogger since
2.0,
>>>>>>>> performance improves a little up to 4M ops/sec.
>>>>>>>> However, when completely reverting AsyncLogger source to
the 2.0
>>>>>>>> version, performance is back to 7.5M ops/sec.
>>>>>>>>
>>>>>>>> I'll try starting from the 2.0 source and getting back to
2.6
>>>>>>>> functionality without losing performance...
>>>>>>>> (Lengthy process...)
>>>>>>>>
>>>>>>>>
>>>>>>>> On Sat, Feb 27, 2016 at 12:18 PM, Remko Popma <
>>>>>>>> remko.popma@gmail.com> wrote:
>>>>>>>>
>>>>>>>>> This is the PerfTestDriver test class (in log4j-core/test,
package
>>>>>>>>> ...async.perf).
>>>>>>>>> Mainly perf3PlainNoLocation.xml:
>>>>>>>>> RollingRandomAccessFileAppender, PatternLayout, all loggers
are
>>>>>>>>> AsyncLoggers, logging a simple string without parameters.
>>>>>>>>>
>>>>>>>>> Profiling with YourKit did not tell me anything useful.
>>>>>>>>>
>>>>>>>>> I'm now eliminating the effect of Layouts/Appenders,
using
>>>>>>>>> CountingNoOpAppender, and seeing similar numbers. So
this seems to be
>>>>>>>>> mostly an issue in AsyncLogger.
>>>>>>>>>
>>>>>>>>> I'll let you know when I find out more.
>>>>>>>>> There's a lot of trial and error here, so this may take
a while...
>>>>>>>>>
>>>>>>>>> Remko
>>>>>>>>>
>>>>>>>>> Sent from my iPhone
>>>>>>>>>
>>>>>>>>> On 2016/02/26, at 21:02, Mikael Ståldal <mikael.staldal@magine.com>
>>>>>>>>> wrote:
>>>>>>>>>
>>>>>>>>> Which components (appenders, layouts) are involved in
the tests?
>>>>>>>>> Would it be possible to do some profiling to see if there
is any particular
>>>>>>>>> component which is to blame?
>>>>>>>>>
>>>>>>>>> On Fri, Feb 26, 2016 at 12:51 PM, Remko Popma <
>>>>>>>>> remko.popma@gmail.com> wrote:
>>>>>>>>>
>>>>>>>>>> To give you some rough impression on concrete numbers
for this
>>>>>>>>>> trend:
>>>>>>>>>> 2.0: ~6M ops/sec
>>>>>>>>>> 2.1-2.2: ~5M ops/sec
>>>>>>>>>> 2.3-2.4: ~3-4M ops/sec
>>>>>>>>>> 2.5: ~3M ops/sec
>>>>>>>>>> 2.6: ~2M ops/sec
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> On Friday, 26 February 2016, Remko Popma <remko.popma@gmail.com>
>>>>>>>>>> wrote:
>>>>>>>>>>
>>>>>>>>>>> You're absolutely right. I still have quite a
few unit tests to
>>>>>>>>>>> add.
>>>>>>>>>>>
>>>>>>>>>>> Initial perf testing shows a downward trend in
Async Logger
>>>>>>>>>>> performance with every release. (Logging simple
string messages
>>>>>>>>>>> without params.) This is worrisome and I'm focusing
on figuring that out
>>>>>>>>>>> first: this will likely involve additional code
changes and I'll add more
>>>>>>>>>>> tests after that.
>>>>>>>>>>>
>>>>>>>>>>> Sent from my iPhone
>>>>>>>>>>>
>>>>>>>>>>> On 2016/02/26, at 10:38, Gary Gregory <garydgregory@gmail.com>
>>>>>>>>>>> wrote:
>>>>>>>>>>>
>>>>>>>>>>> Wow, I love the activity we are seeing toward
2.6! All the perf
>>>>>>>>>>> work on top of an existing sizable change set.
Very exciting indeed.
>>>>>>>>>>>
>>>>>>>>>>> There sure are a lot of changes coming in. I
hope that we all
>>>>>>>>>>> can pitch in to make sure most if not all of
these changes get code
>>>>>>>>>>> coverage from unit tests. I've not checked closely,
but it seems like we
>>>>>>>>>>> may not have good coverage _yet_, or do I have
the wrong impression?
>>>>>>>>>>>
>>>>>>>>>>> I want to make sure we keep our stability in
tip top shape :-)
>>>>>>>>>>> and that we have no regression from previous
releases.
>>>>>>>>>>>
>>>>>>>>>>> Gary
>>>>>>>>>>>
>>>>>>>>>>> --
>>>>>>>>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>>>>>>>>> Java Persistence with Hibernate, Second Edition
>>>>>>>>>>> <http://www.manning.com/bauer3/>
>>>>>>>>>>> JUnit in Action, Second Edition
>>>>>>>>>>> <http://www.manning.com/tahchiev/>
>>>>>>>>>>> Spring Batch in Action <http://www.manning.com/templier/>
>>>>>>>>>>> Blog: http://garygregory.wordpress.com
>>>>>>>>>>> Home: http://garygregory.com/
>>>>>>>>>>> Tweet! http://twitter.com/GaryGregory
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> --
>>>>>>>>> [image: MagineTV]
>>>>>>>>>
>>>>>>>>> *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
>>>>>> <javascript:_e(%7B%7D,'cvml','boards@gmail.com');>>
>>>>>>
>>>>>
>>>>>
>>>>>
>>>>> --
>>>>> Matt Sicker <boards@gmail.com
>>>>> <javascript:_e(%7B%7D,'cvml','boards@gmail.com');>>
>>>>>
>>>>
>>>
>>>
>>> --
>>> Matt Sicker <boards@gmail.com
>>> <javascript:_e(%7B%7D,'cvml','boards@gmail.com');>>
>>>
>>
>>
>>
>> --
>> E-Mail: garydgregory@gmail.com
>> <javascript:_e(%7B%7D,'cvml','garydgregory@gmail.com');> | ggregory@apache.org
>> <javascript:_e(%7B%7D,'cvml','ggregory@apache.org');>
>> Java Persistence with Hibernate, Second Edition
>> <http://www.manning.com/bauer3/>
>> JUnit in Action, Second Edition <http://www.manning.com/tahchiev/>
>> Spring Batch in Action <http://www.manning.com/templier/>
>> Blog: http://garygregory.wordpress.com
>> Home: http://garygregory.com/
>> Tweet! http://twitter.com/GaryGregory
>>
>
>
>
> --
> Matt Sicker <boards@gmail.com
> <javascript:_e(%7B%7D,'cvml','boards@gmail.com');>>
>
>

Mime
View raw message