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 Wed, 23 Mar 2016 00:03:32 GMT
Good news:
The performance gap was not as massive as it originally appeared. One
factor was that the calls to Thread.sleep() during the test skewed the
results. Another issue with the test was that without the sleep(), the
ringbuffer fills up and the BlockingWaitStrategy gives unpredictable
results.

Changing to YieldingWaitStrategy stabilized the test, and the difference
became less pronounced.

2.0: 5.3-5.8 million msg/sec
2.6: was 4.1 million msg/sec, with some small refactoring this improved to
4.7 million msg/sec.


Lesson learnt: I should really create a JMH benchmark for this. Problem in
the past was that I was trying to use JMH with a real Appender, and when
the ringbuffer filled up the producer would block waiting for space to
become available and you'd end up measuring synchronous logging... A
No-Op Appender
solves that problem.

So finally some light at the end of the tunnel.



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

> Thanks. Will take another look.
>
> On Monday, 21 March 2016, Gary Gregory <garydgregory@gmail.com
> <javascript:_e(%7B%7D,'cvml','garydgregory@gmail.com');>> wrote:
>
>> FYI: Yourkit has three profiling modes: sampling, counting and tracing.
>> On Mar 20, 2016 11:47 PM, "Remko Popma" <remko.popma@gmail.com> wrote:
>>
>>> I did try profiling with YourKit and MissionControl but they did not
>>> tell me much. I suppose a sampling profiler does not help much for problems
>>> like this when we are not spending a lot of time in certain methods... I'm
>>> thinking to experiment further with the different event options for perf
>>> stat, and take a look at Oracle Solaris Studio Performance Analyzer.
>>>
>>> There were many changes in 2.4 but most of the performance-related
>>> changes were downstream from the Disruptor in layout etc. They should not
>>> matter since I'm only measuring how fast an application can add simple
>>> string log events in to the ring buffer. (The perf test is with a No-Op
>>> appender.) The only thing that jumps out to me is the nano time support
>>> change... I will experiment with how performance changes if I roll back
>>> that feature.
>>>
>>> I'm not giving up just yet.
>>>
>>>
>>> On Mon, Mar 21, 2016 at 5:17 PM, Ralph Goers <ralph.goers@dslextreme.com
>>> > wrote:
>>>
>>>> Unfortunately there were a lot of changes in 2.4, many of which said
>>>> they were to improve performance. We also switched from Java 6 to Java 7.
>>>>
>>>> Did you try profiling with YourKit?
>>>>
>>>> Ralph
>>>>
>>>> On Mar 20, 2016, at 11:07 PM, Remko Popma <remko.popma@gmail.com>
>>>> wrote:
>>>>
>>>> Quick update on the ongoing investigation in the performance regression:
>>>> I tried running SimplePerfTest on linux with perf stat and got these
>>>> results:
>>>> <investigation20160319_23898_image002.png>
>>>> ​How to read this:
>>>> * Throughput is number of messages logged per second (1.0 ~= 7 million
>>>> msg/sec)
>>>> * Instr/cycle is instructions per clock cycle
>>>> * Branch miss% is the number of branch prediction misses as a
>>>> percentage of all branches
>>>>
>>>> Analysis:
>>>> Throughput of log4j 2.0-2.3 on this machine is about 5.3 million
>>>> msg/sec on average.
>>>> From 2.4, this suddenly gaps down to 3.9 million msg/sec.
>>>> At the same time, the number of branch misses jump up from 0.27% to
>>>> 0.63%, correlating with a much less efficient execution: from 1.47 to 1.06
>>>> instructions per clock cycle.
>>>>
>>>> Conclusion:
>>>> It seems that one or more of the changes made in log4j 2.4 resulted in
>>>> an increase in branch misses during execution.
>>>> This may not be the only problem but it may help to give some direction
>>>> in the search.
>>>>
>>>> Remko
>>>>
>>>> On Thu, Mar 10, 2016 at 3:06 AM, Remko Popma <remko.popma@gmail.com>
>>>> wrote:
>>>>
>>>>> I think you're right, that one should not leak.
>>>>>
>>>>> On Thu, Mar 10, 2016 at 2:40 AM, Matt Sicker <boards@gmail.com> wrote:
>>>>>
>>>>>> I know it's Java 1.8+, but does ThreadLocal.withInitial(Supplier<S>)
>>>>>> prevent that memory leak? They use their own JDK class to subclass
>>>>>> ThreadLocal, so that shouldn't leak.
>>>>>>
>>>>>> On 8 March 2016 at 22:43, Remko Popma <remko.popma@gmail.com> wrote:
>>>>>>
>>>>>>> ThreadLocals containing JDK classes (StringBuilder, etc) are not a
>>>>>>> problem. Their classloader is the system classloader, not the web app
>>>>>>> classloader, so these ThreadLocals do not have a reference to the web app
>>>>>>> classes and do not prevent web app classes from being garbage collected.
>>>>>>>
>>>>>>> This idiom is safe:
>>>>>>>
>>>>>>> class SafeClass {
>>>>>>>     // The type of this field is java.lang.ThreadLocal, and
>>>>>>>     // both the key (ThreadLocal) and the value (StringBuilder) are JDK classes.    // This idiom is safe and will not cause memory leaks in web apps.
>>>>>>>     static ThreadLocal<StringBuilder> safe = new ThreadLocal<StringBuilder>();
>>>>>>>
>>>>>>>     private StringBuilder getThreadLocalStringBuilder() {
>>>>>>>         StringBuilder value = safe.get();
>>>>>>>         if (value == null) {
>>>>>>>             value = new StringBuilder(1024);
>>>>>>>             safe.set(value);
>>>>>>>         }
>>>>>>>         return value;
>>>>>>>     }
>>>>>>> }
>>>>>>>
>>>>>>> However, as soon as we create an anonymous subclass like below we
>>>>>>> cause memory leaks again:
>>>>>>>
>>>>>>> class MemoryLeakingClass {
>>>>>>>     // The type of this field is MemoryLeakingClass$1, an anonymous subclass of java.lang.ThreadLocal!
>>>>>>>     // In a web app, the classloader of this class is the web app class loader: may cause memory leak...
>>>>>>>     static ThreadLocal<StringBuilder> anonymousSubclass = new ThreadLocal<StringBuilder>() {
>>>>>>>
>>>>>>>         @Override
>>>>>>>         protected StringBuilder initialValue() {
>>>>>>>             return new StringBuilder(1024);
>>>>>>>         }
>>>>>>>     };
>>>>>>> }
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> On Wed, Mar 9, 2016 at 11:32 AM, Ralph Goers <
>>>>>>> ralph.goers@dslextreme.com> wrote:
>>>>>>>
>>>>>>>> I still am unclear as to why you are thinking GC-free mode won’t
>>>>>>>> work in web apps.  What is the issue with ThreadLocals that causes the
>>>>>>>> problem?  We are using ThreadLocals for other things that seem to be
>>>>>>>> working.
>>>>>>>>
>>>>>>>> Ralph
>>>>>>>>
>>>>>>>> On Mar 8, 2016, at 3:05 PM, Remko Popma <remko.popma@gmail.com>
>>>>>>>> wrote:
>>>>>>>>
>>>>>>>> Some of the recent changes were to fix issues introduced by the
>>>>>>>> reusable message idea. It is good that we are not rushing this release, and
>>>>>>>> thanks everyone for your patience.
>>>>>>>>
>>>>>>>> I originally wanted to make GC-free mode the default to begin with,
>>>>>>>> but it may be smart to initially require that users switch GC-free mode on
>>>>>>>> explicitly, and only make it the default after it has gained a track
>>>>>>>> record. (Even so, it would only be switched on automatically for non-web
>>>>>>>> apps.)
>>>>>>>>
>>>>>>>> The async logger performance investigation is still ongoing. I hope
>>>>>>>> to be able to resolve it and do the GC-free write-up including performance
>>>>>>>> test results in the next few weeks. I am currently on a business trip,
>>>>>>>> working with people creating low latency trading systems, and they have
>>>>>>>> good ideas on how to investigate the performance regression, so that is
>>>>>>>> helpful.
>>>>>>>>
>>>>>>>> On Wed, Mar 9, 2016 at 4:01 AM, Gary Gregory <
>>>>>>>> garydgregory@gmail.com> wrote:
>>>>>>>>
>>>>>>>>> I'm even more concerned now that more of the no-GC changes are
>>>>>>>>> coming in, still, fast and furious.
>>>>>>>>>
>>>>>>>>> I see what smells like a lot of non-OO code fly by here and there:
>>>>>>>>> lots if-else-if-else-if-else, as opposed to subclassing or delegation if
>>>>>>>>> appropriate.
>>>>>>>>>
>>>>>>>>> Are we rushing toward this no-GC goal without considering speed
>>>>>>>>> performance?
>>>>>>>>>
>>>>>>>>> Where are we on the async logger slow down investigation?
>>>>>>>>>
>>>>>>>>> Concerned and glad to see to much activity all at the same time,
>>>>>>>>> Gary
>>>>>>>>>
>>>>>>>>> On Thu, Mar 3, 2016 at 1:23 PM, Matt Sicker <boards@gmail.com>
>>>>>>>>> wrote:
>>>>>>>>>
>>>>>>>>>> Remko (and anyone else who wants to try and solve this
>>>>>>>>>> regression):
>>>>>>>>>>
>>>>>>>>>> https://www.jclarity.com/product/censum-free-trial/
>>>>>>>>>>
>>>>>>>>>> Go ahead and get the trial and the guys at JClarity will give us
>>>>>>>>>> licenses. I'd use your apache.org email to be safe.
>>>>>>>>>>
>>>>>>>>>> On 3 March 2016 at 11:27, Matt Sicker <boards@gmail.com> wrote:
>>>>>>>>>>
>>>>>>>>>>> So far, Remko's proposal is language-neutral since he defined
>>>>>>>>>>> endianness (big endian like java, but we could use either since ByteBuffer
>>>>>>>>>>> supports both) and field widths..
>>>>>>>>>>>
>>>>>>>>>>> On 3 March 2016 at 03:15, Mikael Ståldal <
>>>>>>>>>>> mikael.staldal@magine.com> wrote:
>>>>>>>>>>>
>>>>>>>>>>>> If we are to design a new binary log event format, then I think
>>>>>>>>>>>> that we should make sure that it is not Java / JVM specific, and that it
>>>>>>>>>>>> will be reasonably easy to implement reading and writing of it on other
>>>>>>>>>>>> platforms.
>>>>>>>>>>>>
>>>>>>>>>>>> On Thu, Mar 3, 2016 at 5:14 AM, Remko Popma <
>>>>>>>>>>>> remko.popma@gmail.com> wrote:
>>>>>>>>>>>>
>>>>>>>>>>>>> I created https://issues.apache.org/jira/browse/LOG4J2-1305 as
>>>>>>>>>>>>> a write up of my current thinking on the topic and a place to discuss
>>>>>>>>>>>>> ideas. Still need to add some things we discussed here
>>>>>>>>>>>>> (tools, endianness, versioning etc).
>>>>>>>>>>>>>
>>>>>>>>>>>>> It's a fascinating topic but I still have a lot of work to do
>>>>>>>>>>>>> on the GC-free epic before I can start working on this one.
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>> On Thursday, 3 March 2016, Remko Popma <remko.popma@gmail.com>
>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>
>>>>>>>>>>>>>> Not Java Serialization, I was thinking simple
>>>>>>>>>>>>>> ByteBuffer.putLong, putInt, putBytes. This is much more performant (
>>>>>>>>>>>>>> http://mechanical-sympathy.blogspot.jp/2012/07/native-cc-like-performance-for-java.html).
>>>>>>>>>>>>>> SBE (Simple Binary Encoding) seems overkill, but open to other opinions.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> The less conditional logic in there the better, so I'm not
>>>>>>>>>>>>>> that interested in configurability. All log event fields,
>>>>>>>>>>>>>> ok. ThreadContextMap/Stack keys and values: similarly to other repeating
>>>>>>>>>>>>>> strings like logger names: write to separate mapping file & only write int
>>>>>>>>>>>>>> values (for count as well as key/value indices) to the "main" log file.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> Two things we would need to decide is how to handle
>>>>>>>>>>>>>> versioning, and what Endianness to use.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> Version information (possibly with schema info) could be
>>>>>>>>>>>>>> written to the log file header.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> Endianness could also be written to the header, or we could
>>>>>>>>>>>>>> simply say we use network byte order (big endian). Intel chips use little
>>>>>>>>>>>>>> endian, but apparently swapping is implemented with an intrinsic and is
>>>>>>>>>>>>>> very fast.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> On Thursday, 3 March 2016, Matt Sicker <boards@gmail.com>
>>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> At that point, it would be nice if it were extensible. There
>>>>>>>>>>>>>>> are some neat binary formats we could use that would allow for that.
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> On 2 March 2016 at 12:09, Gary Gregory <
>>>>>>>>>>>>>>> garydgregory@gmail.com> wrote:
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> I think we'd need to provide all LogEvent fields.
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Gary
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> On Wed, Mar 2, 2016 at 9:13 AM, Remko Popma <
>>>>>>>>>>>>>>>> remko.popma@gmail.com> wrote:
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> That's what I meant, I didn't make myself clear. For
>>>>>>>>>>>>>>>>> example, we could offer a simple binary layout:
>>>>>>>>>>>>>>>>> time stamp (8 bytes)
>>>>>>>>>>>>>>>>> level int (4 bytes)
>>>>>>>>>>>>>>>>> thread ID (4 bytes) - Thread names in separate file
>>>>>>>>>>>>>>>>> Logger ID (4 bytes) - Logger names in separate file.
>>>>>>>>>>>>>>>>> message length (4 bytes)
>>>>>>>>>>>>>>>>> message type (2 bytes)
>>>>>>>>>>>>>>>>> message data (variable length)
>>>>>>>>>>>>>>>>> throwable length (4 bytes)
>>>>>>>>>>>>>>>>> throwable data (variable length)
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> It's a very different approach to logging. On the plus
>>>>>>>>>>>>>>>>> side, this would be extremely compact and very fast to write.
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> On the other hand it would require a separate tool to
>>>>>>>>>>>>>>>>> decode/display the data in human readable form. Such a tool should handle
>>>>>>>>>>>>>>>>> text messages out of the box, but for custom messages I image there could
>>>>>>>>>>>>>>>>> be some plugin mechanism for custom decoders.
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> All very interesting...
>>>>>>>>>>>>>>>>> :-)
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Sent from my iPhone
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> On 2016/03/03, at 0:01, Matt Sicker <boards@gmail.com>
>>>>>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> That's what I thought at first, but he means non-human
>>>>>>>>>>>>>>>>> readable formats since we all use tools to parse logs as it is (Splunk and
>>>>>>>>>>>>>>>>> ELK are the big two I know of).
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> On 2 March 2016 at 02:15, Remko Popma <
>>>>>>>>>>>>>>>>> remko.popma@gmail.com> wrote:
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> Re: binary logging, I think he's talking about providing
>>>>>>>>>>>>>>>>>> an API to log objects directly into byte buffers without turning them into
>>>>>>>>>>>>>>>>>> Strings first.
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> https://issues.apache.org/jira/browse/LOG4J2-1274 and
>>>>>>>>>>>>>>>>>> https://issues.apache.org/jira/browse/LOG4J2-506
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> were created with that in mind and should be a good step
>>>>>>>>>>>>>>>>>> in that direction.
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> Sent from my iPhone
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> On 2016/03/02, at 15:11, Gary Gregory <
>>>>>>>>>>>>>>>>>> garydgregory@gmail.com> wrote:
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> Well, I've often wondered about creating a binary format
>>>>>>>>>>>>>>>>>> but it seems that you could use JSON+ZIP or BSON and get most of the
>>>>>>>>>>>>>>>>>> advantages.
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> Gary
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> On Tue, Mar 1, 2016 at 9:12 PM, Matt Sicker <
>>>>>>>>>>>>>>>>>> boards@gmail.com> wrote:
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>> One other interesting thing I learned is that improper
>>>>>>>>>>>>>>>>>>> use of logging is a huge source of performance problems. The GC-free
>>>>>>>>>>>>>>>>>>> parameterized message factory will help with one aspect of that (I
>>>>>>>>>>>>>>>>>>> suggested parameterized messages, but he countered with the Object[] that
>>>>>>>>>>>>>>>>>>> is created), and encouraging users to use a Supplier<String> instead of
>>>>>>>>>>>>>>>>>>> passing parameters should help as well (especially when those parameters
>>>>>>>>>>>>>>>>>>> have to be computed). He had some strong criticisms of logging APIs
>>>>>>>>>>>>>>>>>>> promoting bad practices which stems all the way back to log4j1 and affects
>>>>>>>>>>>>>>>>>>> pretty much every logging API in Java (some criticisms were actually
>>>>>>>>>>>>>>>>>>> outdated or didn't consider newer features of the API like markers and the
>>>>>>>>>>>>>>>>>>> huge amount of filters available).
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>> His other big idea was promoting the use of binary
>>>>>>>>>>>>>>>>>>> logging formats because humans rarely read the raw log files as it is, but
>>>>>>>>>>>>>>>>>>> it's not like there's a standard way to do that.
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>> Now I kinda wonder if he'll find this thread one day and
>>>>>>>>>>>>>>>>>>> tell me how I misinterpreted him or something. ;)
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>> On 1 March 2016 at 22:28, Matt Sicker <boards@gmail.com>
>>>>>>>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>> Alright, I learned some interesting things. I'm going
>>>>>>>>>>>>>>>>>>>> to get us some tools we can use to try and profile this. Otherwise, he did
>>>>>>>>>>>>>>>>>>>> suggest trying out this project:
>>>>>>>>>>>>>>>>>>>> https://github.com/RichardWarburton/honest-profiler
>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>> On 1 March 2016 at 19:31, Matt Sicker <boards@gmail.com
>>>>>>>>>>>>>>>>>>>> > wrote:
>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>> So far he's said something about using lambdas for
>>>>>>>>>>>>>>>>>>>>> lazy evaluation (though I don't think that would actually help us at all).
>>>>>>>>>>>>>>>>>>>>> I'll try to talk to him one-on-one afterward to delve more into this.
>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>> On 1 March 2016 at 18:13, Ralph Goers <
>>>>>>>>>>>>>>>>>>>>> ralph.goers@dslextreme.com> wrote:
>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>> Actually, most of the tests have the commands in the
>>>>>>>>>>>>>>>>>>>>>> comments right in the class. Just cut and past.
>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>> Ralph
>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>> On Mar 1, 2016, at 1:43 PM, Matt Sicker <
>>>>>>>>>>>>>>>>>>>>>> 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> 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> 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> 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> 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>
>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>>>>>>>>>> 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>
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>>>> 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
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>> 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
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> --
>>>>>>>>>>>> [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>
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> --
>>>>>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> --
>>>>>>>>> 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
>>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>
>>>>>>
>>>>>> --
>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>
>>>>>
>>>>>
>>>>
>>>>
>>>

Mime
View raw message