logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Remko Popma <remko.po...@gmail.com>
Subject Re: Fast and Furious
Date Thu, 03 Mar 2016 04:14:10 GMT
I created https://issues.apache.org/jira/browse/LOG4J2-1305 as a write up
of my current thinking on the topic and a place to discuss ideas. Still
need to add some things we discussed here (tools, endianness, versioning
etc).

It's a fascinating topic but I still have a lot of work to do on the
GC-free epic before I can start working on this one.


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

> Not Java Serialization, I was thinking simple ByteBuffer.putLong, putInt,
> putBytes. This is much more performant (
> http://mechanical-sympathy.blogspot.jp/2012/07/native-cc-like-performance-for-java.html).
> SBE (Simple Binary Encoding) seems overkill, but open to other opinions.
>
> The less conditional logic in there the better, so I'm not that interested
> in configurability. All log event fields, ok. ThreadContextMap/Stack keys
> and values: similarly to other repeating strings like logger names: write
> to separate mapping file & only write int values (for count as well as
> key/value indices) to the "main" log file.
>
> Two things we would need to decide is how to handle versioning, and what
> Endianness to use.
>
> Version information (possibly with schema info) could be written to the
> log file header.
>
> Endianness could also be written to the header, or we could simply say we
> use network byte order (big endian). Intel chips use little endian, but
> apparently swapping is implemented with an intrinsic and is very fast.
>
> On Thursday, 3 March 2016, Matt Sicker <boards@gmail.com
> <javascript:_e(%7B%7D,'cvml','boards@gmail.com');>> wrote:
>
>> At that point, it would be nice if it were extensible. There are some
>> neat binary formats we could use that would allow for that.
>>
>> On 2 March 2016 at 12:09, Gary Gregory <garydgregory@gmail.com> wrote:
>>
>>> I think we'd need to provide all LogEvent fields.
>>>
>>> Gary
>>>
>>> On Wed, Mar 2, 2016 at 9:13 AM, Remko Popma <remko.popma@gmail.com>
>>> wrote:
>>>
>>>> That's what I meant, I didn't make myself clear. For example, we could
>>>> offer a simple binary layout:
>>>> time stamp (8 bytes)
>>>> level int (4 bytes)
>>>> thread ID (4 bytes) - Thread names in separate file
>>>> Logger ID (4 bytes) - Logger names in separate file.
>>>> message length (4 bytes)
>>>> message type (2 bytes)
>>>> message data (variable length)
>>>> throwable length (4 bytes)
>>>> throwable data (variable length)
>>>>
>>>> It's a very different approach to logging. On the plus side, this would
>>>> be extremely compact and very fast to write.
>>>>
>>>> On the other hand it would require a separate tool to decode/display
>>>> the data in human readable form. Such a tool should handle text messages
>>>> out of the box, but for custom messages I image there could be some plugin
>>>> mechanism for custom decoders.
>>>>
>>>> All very interesting...
>>>> :-)
>>>>
>>>> Sent from my iPhone
>>>>
>>>> On 2016/03/03, at 0:01, Matt Sicker <boards@gmail.com> wrote:
>>>>
>>>> That's what I thought at first, but he means non-human readable formats
>>>> since we all use tools to parse logs as it is (Splunk and ELK are the big
>>>> two I know of).
>>>>
>>>> On 2 March 2016 at 02:15, Remko Popma <remko.popma@gmail.com> wrote:
>>>>
>>>>> Re: binary logging, I think he's talking about providing an API to log
>>>>> objects directly into byte buffers without turning them into Strings
first.
>>>>>
>>>>> https://issues.apache.org/jira/browse/LOG4J2-1274 and
>>>>> https://issues.apache.org/jira/browse/LOG4J2-506
>>>>>
>>>>> were created with that in mind and should be a good step in that
>>>>> direction.
>>>>>
>>>>> Sent from my iPhone
>>>>>
>>>>> On 2016/03/02, at 15:11, Gary Gregory <garydgregory@gmail.com>
wrote:
>>>>>
>>>>> Well, I've often wondered about creating a binary format but it seems
>>>>> that you could use JSON+ZIP or BSON and get most of the advantages.
>>>>>
>>>>> Gary
>>>>>
>>>>> On Tue, Mar 1, 2016 at 9:12 PM, Matt Sicker <boards@gmail.com>
wrote:
>>>>>
>>>>>> One other interesting thing I learned is that improper use of logging
>>>>>> is a huge source of performance problems. The GC-free parameterized
message
>>>>>> factory will help with one aspect of that (I suggested parameterized
>>>>>> messages, but he countered with the Object[] that is created), and
>>>>>> encouraging users to use a Supplier<String> instead of passing
parameters
>>>>>> should help as well (especially when those parameters have to be
computed).
>>>>>> He had some strong criticisms of logging APIs promoting bad practices
which
>>>>>> stems all the way back to log4j1 and affects pretty much every logging
API
>>>>>> in Java (some criticisms were actually outdated or didn't consider
newer
>>>>>> features of the API like markers and the huge amount of filters available).
>>>>>>
>>>>>> His other big idea was promoting the use of binary logging formats
>>>>>> because humans rarely read the raw log files as it is, but it's not
like
>>>>>> there's a standard way to do that.
>>>>>>
>>>>>> Now I kinda wonder if he'll find this thread one day and tell me
how
>>>>>> I misinterpreted him or something. ;)
>>>>>>
>>>>>> On 1 March 2016 at 22:28, Matt Sicker <boards@gmail.com> wrote:
>>>>>>
>>>>>>> Alright, I learned some interesting things. I'm going to get
us some
>>>>>>> tools we can use to try and profile this. Otherwise, he did suggest
trying
>>>>>>> out this project:
>>>>>>> https://github.com/RichardWarburton/honest-profiler
>>>>>>>
>>>>>>> On 1 March 2016 at 19:31, Matt Sicker <boards@gmail.com>
wrote:
>>>>>>>
>>>>>>>> So far he's said something about using lambdas for lazy evaluation
>>>>>>>> (though I don't think that would actually help us at all).
I'll try to talk
>>>>>>>> to him one-on-one afterward to delve more into this.
>>>>>>>>
>>>>>>>> On 1 March 2016 at 18:13, Ralph Goers <ralph.goers@dslextreme.com>
>>>>>>>> wrote:
>>>>>>>>
>>>>>>>>> Actually, most of the tests have the commands in the
comments
>>>>>>>>> right in the class. Just cut and past.
>>>>>>>>>
>>>>>>>>> Ralph
>>>>>>>>>
>>>>>>>>> On Mar 1, 2016, at 1:43 PM, Matt Sicker <boards@gmail.com>
wrote:
>>>>>>>>>
>>>>>>>>> I can't even figure out how to execute the simple perf
test class.
>>>>>>>>> IntelliJ gives me some annotation processing error, and
doing it from the
>>>>>>>>> command line is turning into a classpath nightmare to
figure out what jars
>>>>>>>>> are needed to execute the test manually.
>>>>>>>>>
>>>>>>>>> On 1 March 2016 at 11:34, Gary Gregory <garydgregory@gmail.com>
>>>>>>>>> wrote:
>>>>>>>>>
>>>>>>>>>> Before the talk: Hi, I'm Remko, I help on Apache
Log4j, are you
>>>>>>>>>> available after the preso to talk about some issue
we are seeing?
>>>>>>>>>>
>>>>>>>>>> Gary
>>>>>>>>>> On Mar 1, 2016 8:29 AM, "Matt Sicker" <boards@gmail.com>
wrote:
>>>>>>>>>>
>>>>>>>>>>> I'm attending a JUG meetup tonight with Kirk
Pepperdine
>>>>>>>>>>> presenting. It's supposed to be a Java performance
workshop type of thing,
>>>>>>>>>>> so if you've got a decent way to ask about it,
I could see if he can help
>>>>>>>>>>> figure out this regression. I can at least show
off the SimplePerfTest and
>>>>>>>>>>> any microbenchmarks we have.
>>>>>>>>>>>
>>>>>>>>>>> On 28 February 2016 at 11:54, Matt Sicker <boards@gmail.com>
>>>>>>>>>>> wrote:
>>>>>>>>>>>
>>>>>>>>>>>> Take a look at the git bisect command. Might
help you find
>>>>>>>>>>>> which changes caused the problem.
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> On Sunday, 28 February 2016, Gary Gregory
<
>>>>>>>>>>>> garydgregory@gmail.com> wrote:
>>>>>>>>>>>>
>>>>>>>>>>>>> Thank you for digging in Remko. This
is will be a nice theme
>>>>>>>>>>>>> to publicize when you get it figured
out.
>>>>>>>>>>>>>
>>>>>>>>>>>>> Gary
>>>>>>>>>>>>> On Feb 28, 2016 4:08 AM, "Remko Popma"
<remko.popma@gmail.com>
>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>
>>>>>>>>>>>>>> After removing the potential impact
of appenders and layouts
>>>>>>>>>>>>>> by testing with log4j-core\src\test\resources\perf-CountingNoOpAppender.xml
>>>>>>>>>>>>>> and org.apache.logging.log4j.core.async.perftest.SimplePerfTest,
I've
>>>>>>>>>>>>>> confirmed my initial numbers:
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> 2.0: 7.5M ops/sec
>>>>>>>>>>>>>> 2.1: 6M ops/sec
>>>>>>>>>>>>>> 2.2: 6M ops/sec
>>>>>>>>>>>>>> 2.3: 6M ops/sec
>>>>>>>>>>>>>> 2.4: 4.5M ops/sec
>>>>>>>>>>>>>> 2.5: 4M ops/sec
>>>>>>>>>>>>>> 2.6: 2M ops/sec
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> I tried reverting various changes
made to AsyncLogger since
>>>>>>>>>>>>>> 2.0, performance improves a little
up to 4M ops/sec.
>>>>>>>>>>>>>> However, when completely reverting
AsyncLogger source to the
>>>>>>>>>>>>>> 2.0 version, performance is back
to 7.5M ops/sec.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> I'll try starting from the 2.0 source
and getting back to 2.6
>>>>>>>>>>>>>> functionality without losing performance...
>>>>>>>>>>>>>> (Lengthy process...)
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> On Sat, Feb 27, 2016 at 12:18 PM,
Remko Popma <
>>>>>>>>>>>>>> remko.popma@gmail.com> wrote:
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> This is the PerfTestDriver test
class (in log4j-core/test,
>>>>>>>>>>>>>>> package ...async.perf).
>>>>>>>>>>>>>>> Mainly perf3PlainNoLocation.xml:
>>>>>>>>>>>>>>> RollingRandomAccessFileAppender,
PatternLayout, all loggers
>>>>>>>>>>>>>>> are AsyncLoggers, logging a simple
string without parameters.
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Profiling with YourKit did not
tell me anything useful.
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> I'm now eliminating the effect
of Layouts/Appenders, using
>>>>>>>>>>>>>>> CountingNoOpAppender, and seeing
similar numbers. So this seems to be
>>>>>>>>>>>>>>> mostly an issue in AsyncLogger.
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> I'll let you know when I find
out more.
>>>>>>>>>>>>>>> There's a lot of trial and error
here, so this may take a
>>>>>>>>>>>>>>> while...
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Remko
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Sent from my iPhone
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> On 2016/02/26, at 21:02, Mikael
Ståldal <
>>>>>>>>>>>>>>> mikael.staldal@magine.com>
wrote:
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Which components (appenders,
layouts) are involved in the
>>>>>>>>>>>>>>> tests? Would it be possible to
do some profiling to see if there is any
>>>>>>>>>>>>>>> particular component which is
to blame?
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> On Fri, Feb 26, 2016 at 12:51
PM, Remko Popma <
>>>>>>>>>>>>>>> remko.popma@gmail.com> wrote:
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> To give you some rough impression
on concrete numbers for
>>>>>>>>>>>>>>>> this trend:
>>>>>>>>>>>>>>>> 2.0: ~6M ops/sec
>>>>>>>>>>>>>>>> 2.1-2.2: ~5M ops/sec
>>>>>>>>>>>>>>>> 2.3-2.4: ~3-4M ops/sec
>>>>>>>>>>>>>>>> 2.5: ~3M ops/sec
>>>>>>>>>>>>>>>> 2.6: ~2M ops/sec
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> On Friday, 26 February 2016,
Remko Popma <
>>>>>>>>>>>>>>>> remko.popma@gmail.com>
wrote:
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> You're absolutely right.
I still have quite a few unit
>>>>>>>>>>>>>>>>> tests to add.
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Initial perf testing
shows a downward trend in Async
>>>>>>>>>>>>>>>>> Logger performance with
every release. (Logging simple
>>>>>>>>>>>>>>>>> string messages without
params.) This is worrisome and I'm focusing on
>>>>>>>>>>>>>>>>> figuring that out first:
this will likely involve additional code changes
>>>>>>>>>>>>>>>>> and I'll add more tests
after that.
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Sent from my iPhone
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> On 2016/02/26, at 10:38,
Gary Gregory <
>>>>>>>>>>>>>>>>> garydgregory@gmail.com>
wrote:
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Wow, I love the activity
we are seeing toward 2.6! All the
>>>>>>>>>>>>>>>>> perf work on top of an
existing sizable change set. Very exciting indeed.
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> There sure are a lot
of changes coming in. I hope that we
>>>>>>>>>>>>>>>>> all can pitch in to make
sure most if not all of these changes get code
>>>>>>>>>>>>>>>>> coverage from unit tests.
I've not checked closely, but it seems like we
>>>>>>>>>>>>>>>>> may not have good coverage
_yet_, or do I have the wrong impression?
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> I want to make sure we
keep our stability in tip top shape
>>>>>>>>>>>>>>>>> :-) and that we have
no regression from previous releases.
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Gary
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>>> E-Mail: garydgregory@gmail.com
| ggregory@apache.org
>>>>>>>>>>>>>>>>> Java Persistence with
Hibernate, Second Edition
>>>>>>>>>>>>>>>>> <http://www.manning.com/bauer3/>
>>>>>>>>>>>>>>>>> JUnit in Action, Second
Edition
>>>>>>>>>>>>>>>>> <http://www.manning.com/tahchiev/>
>>>>>>>>>>>>>>>>> Spring Batch in Action
<http://www.manning.com/templier/>
>>>>>>>>>>>>>>>>> Blog: http://garygregory.wordpress.com
>>>>>>>>>>>>>>>>> Home: http://garygregory.com/
>>>>>>>>>>>>>>>>> Tweet! http://twitter.com/GaryGregory
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>> [image: MagineTV]
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> *Mikael Ståldal*
>>>>>>>>>>>>>>> Senior software developer
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> *Magine TV*
>>>>>>>>>>>>>>> mikael.staldal@magine.com
>>>>>>>>>>>>>>> Grev Turegatan 3  | 114 46 Stockholm,
Sweden  |
>>>>>>>>>>>>>>> www.magine.com
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Privileged and/or Confidential
Information may be contained
>>>>>>>>>>>>>>> in this message. If you are not
the addressee indicated in this message
>>>>>>>>>>>>>>> (or responsible for delivery
of the message to such a
>>>>>>>>>>>>>>> person), you may not copy or
deliver this message to anyone. In such case,
>>>>>>>>>>>>>>> you should destroy this message
and kindly notify the sender
>>>>>>>>>>>>>>> by reply email.
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> --
>>>>>>>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> --
>>>>>>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> --
>>>>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> --
>>>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> --
>>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> --
>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>
>>>>>
>>>>>
>>>>>
>>>>> --
>>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>>> Java Persistence with Hibernate, Second Edition
>>>>> <http://www.manning.com/bauer3/>
>>>>> JUnit in Action, Second Edition <http://www.manning.com/tahchiev/>
>>>>> Spring Batch in Action <http://www.manning.com/templier/>
>>>>> Blog: http://garygregory.wordpress.com
>>>>> Home: http://garygregory.com/
>>>>> Tweet! http://twitter.com/GaryGregory
>>>>>
>>>>>
>>>>
>>>>
>>>> --
>>>> Matt Sicker <boards@gmail.com>
>>>>
>>>>
>>>
>>>
>>> --
>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>> Java Persistence with Hibernate, Second Edition
>>> <http://www.manning.com/bauer3/>
>>> JUnit in Action, Second Edition <http://www.manning.com/tahchiev/>
>>> Spring Batch in Action <http://www.manning.com/templier/>
>>> Blog: http://garygregory.wordpress.com
>>> Home: http://garygregory.com/
>>> Tweet! http://twitter.com/GaryGregory
>>>
>>
>>
>>
>> --
>> Matt Sicker <boards@gmail.com>
>>
>

Mime
View raw message