logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Mikael Ståldal <mikael.stal...@magine.com>
Subject Re: Fast and Furious
Date Thu, 03 Mar 2016 09:15:46 GMT
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.popma@gmail.com> 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 <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> 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>
>>>
>>


-- 
[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.

Mime
View raw message