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.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). > 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 > <javascript:_e(%7B%7D,'cvml','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 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 <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 >>>>>>> >>>>>>> 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 >>>>>>>>>>>>>>>>> Home: http://garygregory.com/ >>>>>>>>>>>>>>>>> Tweet! http://twitter.com/GaryGregory >>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>> >>>>>>>>>>>>>>> >>>>>>>>>>>>>>> -- >>>>>>>>>>>>>>> [image: MagineTV] >>>>>>>>>>>>>>> >>>>>>>>>>>>>>> *Mikael Ståldal* >>>>>>>>>>>>>>> Senior software developer >>>>>>>>>>>>>>> >>>>>>>>>>>>>>> *Magine TV* >>>>>>>>>>>>>>> mikael.stal...@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 <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 >>>>> Home: http://garygregory.com/ >>>>> Tweet! 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 >>> Home: http://garygregory.com/ >>> Tweet! http://twitter.com/GaryGregory >>> >> >> >> >> -- >> Matt Sicker <boa...@gmail.com> >> >
