logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Matt Sicker <boa...@gmail.com>
Subject Re: Fast and Furious
Date Thu, 03 Mar 2016 17:27:15 GMT
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.staldal@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.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.
>



-- 
Matt Sicker <boards@gmail.com>

Mime
View raw message