That's some great news! On 22 March 2016 at 19:03, Remko Popma <[email protected]> wrote:
> 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]> 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]> >>>>>>> >>>>>> >>>>>> >>>>> >>>>> >>>> -- Matt Sicker <[email protected]>
