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.po...@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.po...@gmail.com > <mailto:remko.po...@gmail.com>> wrote: > I think you're right, that one should not leak. > > On Thu, Mar 10, 2016 at 2:40 AM, Matt Sicker <boa...@gmail.com > <mailto:boa...@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.po...@gmail.com > <mailto:remko.po...@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.go...@dslextreme.com > <mailto:ralph.go...@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.po...@gmail.com >> <mailto:remko.po...@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 <garydgreg...@gmail.com >> <mailto:garydgreg...@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 <boa...@gmail.com >> <mailto:boa...@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 <http://apache.org/> email to be safe. >> >> On 3 March 2016 at 11:27, Matt Sicker <boa...@gmail.com >> <mailto:boa...@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.stal...@magine.com >> <mailto:mikael.stal...@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.po...@gmail.com >> <mailto:remko.po...@gmail.com>> wrote: >> I created https://issues.apache.org/jira/browse/LOG4J2-1305 >> <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.po...@gmail.com >> <mailto:remko.po...@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 >> >> <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 <boa...@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 <garydgreg...@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.po...@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 <boa...@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.po...@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 >>> <https://issues.apache.org/jira/browse/LOG4J2-1274> and >>> https://issues.apache.org/jira/browse/LOG4J2-506 >>> <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 <garydgreg...@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 <boa...@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 <boa...@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 >>>> <https://github.com/RichardWarburton/honest-profiler> >>>> >>>> On 1 March 2016 at 19:31, Matt Sicker <boa...@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.go...@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 <boa...@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 <garydgreg...@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" <boa...@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 <boa...@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 <garydgreg...@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.po...@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.po...@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.stal...@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.po...@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.po...@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 <garydgreg...@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: garydgreg...@gmail.com <> | ggreg...@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 >>>>>>> <http://garygregory.wordpress.com/> >>>>>>> Home: http://garygregory.com/ <http://garygregory.com/> >>>>>>> Tweet! http://twitter.com/GaryGregory <http://twitter.com/GaryGregory> >>>>>> >>>>>> >>>>>> -- >>>>>> >>>>>> >>>>>> Mikael Ståldal >>>>>> Senior software developer >>>>>> >>>>>> Magine TV >>>>>> mikael.stal...@magine.com <> >>>>>> Grev Turegatan 3 | 114 46 Stockholm, Sweden | www.magine.com >>>>>> <http://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 <boa...@gmail.com <>> >>>>> >>>>> >>>>> >>>>> -- >>>>> Matt Sicker <boa...@gmail.com <>> >>>>> >>>>> >>>>> >>>>> -- >>>>> Matt Sicker <boa...@gmail.com <>> >>>> >>>> >>>> >>>> >>>> -- >>>> Matt Sicker <boa...@gmail.com <>> >>>> >>>> >>>> >>>> -- >>>> Matt Sicker <boa...@gmail.com <>> >>>> >>>> >>>> >>>> -- >>>> Matt Sicker <boa...@gmail.com <>> >>>> >>>> >>>> >>>> -- >>>> E-Mail: garydgreg...@gmail.com <> | ggreg...@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 <http://garygregory.wordpress.com/> >>>> Home: http://garygregory.com/ <http://garygregory.com/> >>>> Tweet! http://twitter.com/GaryGregory <http://twitter.com/GaryGregory> >>> >>> >>> -- >>> Matt Sicker <boa...@gmail.com <>> >> >> >> >> -- >> E-Mail: garydgreg...@gmail.com <> | ggreg...@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 <http://garygregory.wordpress.com/> >> Home: http://garygregory.com/ <http://garygregory.com/> >> Tweet! http://twitter.com/GaryGregory <http://twitter.com/GaryGregory> >> >> >> -- >> Matt Sicker <boa...@gmail.com <>> >> >> >> >> -- >> >> >> Mikael Ståldal >> Senior software developer >> >> Magine TV >> mikael.stal...@magine.com <mailto:mikael.stal...@magine.com> >> Grev Turegatan 3 | 114 46 Stockholm, Sweden | www.magine.com >> <http://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 <boa...@gmail.com <mailto:boa...@gmail.com>> >> >> >> >> -- >> Matt Sicker <boa...@gmail.com <mailto:boa...@gmail.com>> >> >> >> >> -- >> E-Mail: garydgreg...@gmail.com <mailto:garydgreg...@gmail.com> | >> ggreg...@apache.org <mailto:ggreg...@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 <http://garygregory.wordpress.com/> >> Home: http://garygregory.com/ <http://garygregory.com/> >> Tweet! http://twitter.com/GaryGregory <http://twitter.com/GaryGregory> > > > > > > -- > Matt Sicker <boa...@gmail.com <mailto:boa...@gmail.com>> > >
