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 <[email protected]> wrote: > Thanks. Will take another look. > > On Monday, 21 March 2016, Gary Gregory <[email protected] > <javascript:_e(%7B%7D,'cvml','[email protected]');>> wrote: > >> FYI: Yourkit has three profiling modes: sampling, counting and tracing. >> On Mar 20, 2016 11:47 PM, "Remko Popma" <[email protected]> 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 <[email protected] >>> > 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 <[email protected]> >>>> 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 <[email protected]> >>>> wrote: >>>> >>>>> I think you're right, that one should not leak. >>>>> >>>>> On Thu, Mar 10, 2016 at 2:40 AM, Matt Sicker <[email protected]> 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 <[email protected]> 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 < >>>>>>> [email protected]> 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 <[email protected]> >>>>>>>> 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 < >>>>>>>> [email protected]> 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 <[email protected]> >>>>>>>>> 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 <[email protected]> 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 < >>>>>>>>>>> [email protected]> 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 < >>>>>>>>>>>> [email protected]> 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 <[email protected]> >>>>>>>>>>>>> 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 <[email protected]> >>>>>>>>>>>>>> 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 < >>>>>>>>>>>>>>> [email protected]> wrote: >>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> I think we'd need to provide all LogEvent fields. >>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> Gary >>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> On Wed, Mar 2, 2016 at 9:13 AM, Remko Popma < >>>>>>>>>>>>>>>> [email protected]> 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 <[email protected]> >>>>>>>>>>>>>>>>> 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 < >>>>>>>>>>>>>>>>> [email protected]> 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 < >>>>>>>>>>>>>>>>>> [email protected]> 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 < >>>>>>>>>>>>>>>>>> [email protected]> 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 <[email protected]> >>>>>>>>>>>>>>>>>>> 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 <[email protected] >>>>>>>>>>>>>>>>>>>> > 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 < >>>>>>>>>>>>>>>>>>>>> [email protected]> 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 < >>>>>>>>>>>>>>>>>>>>>> [email protected]> 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 < >>>>>>>>>>>>>>>>>>>>>> [email protected]> 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" < >>>>>>>>>>>>>>>>>>>>>>> [email protected]> 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 < >>>>>>>>>>>>>>>>>>>>>>>> [email protected]> 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 < >>>>>>>>>>>>>>>>>>>>>>>>> [email protected]> 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" < >>>>>>>>>>>>>>>>>>>>>>>>>> [email protected]> 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 < >>>>>>>>>>>>>>>>>>>>>>>>>>> [email protected]> 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 < >>>>>>>>>>>>>>>>>>>>>>>>>>>> [email protected]> 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 < >>>>>>>>>>>>>>>>>>>>>>>>>>>> [email protected]> 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 < >>>>>>>>>>>>>>>>>>>>>>>>>>>>> [email protected]> 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 < >>>>>>>>>>>>>>>>>>>>>>>>>>>>>> [email protected]> 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: [email protected] | >>>>>>>>>>>>>>>>>>>>>>>>>>>>>> [email protected] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>>>>>>>>>>>>> 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* >>>>>>>>>>>>>>>>>>>>>>>>>>>> [email protected] >>>>>>>>>>>>>>>>>>>>>>>>>>>> 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 <[email protected]> >>>>>>>>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>>>>>>> -- >>>>>>>>>>>>>>>>>>>>>>>> Matt Sicker <[email protected]> >>>>>>>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>>>>> -- >>>>>>>>>>>>>>>>>>>>>> Matt Sicker <[email protected]> >>>>>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>>>> -- >>>>>>>>>>>>>>>>>>>>> Matt Sicker <[email protected]> >>>>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>>> -- >>>>>>>>>>>>>>>>>>>> Matt Sicker <[email protected]> >>>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>>> -- >>>>>>>>>>>>>>>>>>> Matt Sicker <[email protected]> >>>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>> -- >>>>>>>>>>>>>>>>>> E-Mail: [email protected] | [email protected] >>>>>>>>>>>>>>>>>> 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 <[email protected]> >>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> -- >>>>>>>>>>>>>>>> E-Mail: [email protected] | [email protected] >>>>>>>>>>>>>>>> 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 <[email protected]> >>>>>>>>>>>>>>> >>>>>>>>>>>>>> >>>>>>>>>>>> >>>>>>>>>>>> >>>>>>>>>>>> -- >>>>>>>>>>>> [image: MagineTV] >>>>>>>>>>>> >>>>>>>>>>>> *Mikael Ståldal* >>>>>>>>>>>> Senior software developer >>>>>>>>>>>> >>>>>>>>>>>> *Magine TV* >>>>>>>>>>>> [email protected] >>>>>>>>>>>> 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 <[email protected]> >>>>>>>>>>> >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> -- >>>>>>>>>> Matt Sicker <[email protected]> >>>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>>> -- >>>>>>>>> E-Mail: [email protected] | [email protected] >>>>>>>>> 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 <[email protected]> >>>>>> >>>>> >>>>> >>>> >>>> >>>
