log5j ... an async log framework that is has less contention and better performance than log4j

[Kevin Burton]

I created this a few years back:

http://code.google.com/p/log5j/

We use it in production at work and I heard Martin complaining in one of his talks about log4j and other logging facades so I thought I would post it.

It uses log4j under the covers and accepts writes into a queue and then drains that queue to disk.

The only time writers block is if the queue fills up (obviously).  

It also supports printf so if you have lots of log.debug() code you don't end up with garbage being created from creating new strings which are NEVER logged.

It's been a few years since I worked on it.

It does have one annoying bug which I should fix and that's how to handle correct shutdown.  You have to sync the log on shutdown and traditionally log4j didn't require this so we didn't implement it internally as it would require us to refactor a lot of code.

I'd like to fix that though.

I should also probably move it over to github... 

[Simone Bordet]

Hi,

On Wed, Jun 12, 2013 at 5:51 PM, Kevin Burton <burto...@gmail.com> wrote:
> I created this a few years back:
>
> http://code.google.com/p/log5j/
>
> We use it in production at work and I heard Martin complaining in one of his
> talks about log4j and other logging facades so I thought I would post it.
>
> It uses log4j under the covers and accepts writes into a queue and then
> drains that queue to disk.

Can you highlight how this is different from Log4J's AsyncAppender ?

--
Simone Bordet
----
http://cometd.org
http://webtide.com
http://intalio.com
Developer advice, training, services and support
from the Jetty & CometD experts.
Intalio, the modern way to build business applications.

[Kevin Burton]

Interesting.  I hadn't seen that they had updated their AsyncLogger. I assume my code is not obsolete (good!  less for me to maintain!) now... 

Though it has two nice features.  It can compute the class name just with a constructor and it supports printf syntax.  I need to see if log4j 2.0 does that now. I hope it does... that would rock.

[Scott Carey]

I've been happy with slf4j's syntax for formatting strings (which is much faster than printf or String.format).  It can be configured to output to just about anything, and forward other logging framework traffic to it.

Can you compute the nested class name in static context?  Logging references as member variables per instance is not so great for memory consumption.

[Edward Sargisson]

Log4j2 is under very active development. I would suspect the maintainers would be very interested in new ideas or code. I'll CC Ralph Goers from log4j2 in in case he has a comment.

Cheers,
Edward

On Wednesday, June 12, 2013 11:33:26 AM UTC-7, Kevin Burton wrote:

[Peter Lawrey]

Perhaps Chronicle 2.0 would be of interest.  It is close to release and can support persisting up to 70 million messages per second with *synchronous* writes. i.e. you don't need to worry about flushing an asynchronous queue as the program can suffer a JVM crash on the next line of code and the message won't be lost.

Regards,

   Peter.

--
You received this message because you are subscribed to the Google Groups "mechanical-sympathy" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mechanical-symp...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

[Kevin Burton]

Do people REALLY log this much? I mean at a conservative 40 bytes per log line that's 2.8GB per second of log message…

I think I log maybe 1-2 messages a minute.

My biggest concern is excessive log.debug causing garbage and referencing a synchronized or a lock.

To unsubscribe from this group and stop receiving emails from it, send an email to mechanical-sympathy+unsub...@googlegroups.com.

[Michael Barker]

> Perhaps Chronicle 2.0 would be of interest. It is close to release and can
> support persisting up to 70 million messages per second with *synchronous*
> writes. i.e. you don't need to worry about flushing an asynchronous queue as
> the program can suffer a JVM crash on the next line of code and the message
> won't be lost.

Is that synchronous to disk or to the OS page cache?

Mike.

[Remko Popma]

Kevin,

The default syntax in Log4j 2.0 is like slf4j: logger.info("... {} ...", arg).

It also supports printf syntax by specifying a different MessageFactory when getting the Logger from the LogManager.

But as Scott mentions, the slf4j syntax is faster (I haven't tested this myself).

Can you elaborate on the other feature you mention, computing the class name with a constructor?

[Simone Bordet]

Hi,

On Thu, Jun 13, 2013 at 11:48 PM, Remko Popma <remko...@gmail.com> wrote:
> Kevin,
>
> The default syntax in Log4j 2.0 is like slf4j: logger.info("... {} ...",
> arg).
> It also supports printf syntax by specifying a different MessageFactory when
> getting the Logger from the LogManager.
> But as Scott mentions, the slf4j syntax is faster (I haven't tested this
> myself).
>
> Can you elaborate on the other feature you mention, computing the class name
> with a constructor?

Is it the new Object(){}.getClass().getEnclosingClass() trick used to
compute the class name from a static context ?

--
Simone Bordet
http://bordet.blogspot.com
---
Finally, no matter how good the architecture and design are,
to deliver bug-free software with optimal performance and reliability,
the implementation technique must be flawless. Victoria Livschitz

[Peter Lawrey]

This is used for more than just logging. It is also a logged IPC messaging between threads/processes.  In low latency trading you often have micro-bursts of activity. i.e. about 0.1 % of the time you are 100% busy and a couple of MB per second is reasonable.  You don't want any delays if you can avoid them.  Chronicle supports writing and reading text and binary without creating objects (or supports object pools so it can be minimised) None of the write methods create objects.  Chronicle 1.7 supports IPC around 100 nano-seconds and Chronicle 2.0 is planned to be 3x faster.  In trading, you want to record every event in the system so you can trace with micro-seconds timing where any delay occurred and why.  It also allows you to replay production data in testing so you can ensure any issues you have are reproduce-able.

While Chronicle supports fsync on every write, the default is just flushed to the OS.

On 13 June 2013 14:59, Kevin Burton <bur...@spinn3r.com> wrote:

Do people REALLY log this much? I mean at a conservative 40 bytes per log line that's 2.8GB per second of log message…

I think I log maybe 1-2 messages a minute.

My biggest concern is excessive log.debug causing garbage and referencing a synchronized or a lock.

Kevin

--

Founder/CEO Spinn3r.com

Location: San Francisco, CA
Skype: burtonator

blog: http://burtonator.wordpress.com

… or check out my Google+ profile

War is peace. Freedom is slavery. Ignorance is strength. Corporations are people.

[Kevin Burton]

Ah... yeah.  I think that makes sense.  I also just realized that in Peregrine it would be nice to enable the full query log with a threshold of 0ms so that I can capture *all* GET/SCAN queries and replay them.  

On semi loaded machine you would want that to be as fast as possible.

To unsubscribe from this group and stop receiving emails from it, send an email to mechanical-sympathy+unsub...@googlegroups.com.

For more options, visit https://groups.google.com/groups/opt_out.
 
 

[Peter Lawrey]

My "unoffical" aim is to make the creation of a persisted message close to the time it takes to create/copy a new object with the same information. This removes any gain you might have by having asynchronous logging.

To unsubscribe from this group and stop receiving emails from it, send an email to mechanical-symp...@googlegroups.com.

[Kirk Pepperdine]

Hi Peter,

I've been railing against Log4J, JDK logging and more recently LogBack for being completely inadequate as logging frameworks. I don't see that logback or SLF4J have really addressed any of the multitude of problems that are presented when using these frameworks. In addition, the similar ill thought out sloppy interfaces were proposed in JEP158 with the Unified JVM logging framework. I've included Markus Eisele here because we're of like minds on the problems. Markus has started a project on defining a better logging API .

I probably shouldn't be writing this email right now as I'm about to head out so that I can get home which means that I really can't layout the problems here in a meaningful way. But, I'll list what are IMHO the three biggest offences

1) Hierarchical tag system that forces one to eat the entire layers of the cake when all you may need is a slice.

2) API's that encourage excessive String manipulation before the call is even made to see if the data is needed or not.

3) XML configuration files ( this just is so wrong on so many levels....)

I've also not taken a serious look at Chronicle and though I completely trust that your performance numbers are correct I'm left wondering what Java Chronicle does to address any of these other problems?

Sorry for the hit and run but...

-- Kirk

[Richard Warburton]

Hi,

I probably shouldn't be writing this email right now as I'm about to head out so that I can get home which means that I really can't layout the problems here in a meaningful way. But, I'll list what are IMHO the three biggest offences

I pretty much think all of these are solved, or semi-solved issues if you look just a little below the surface.

1) Hierarchical tag system that forces one to eat the entire layers of the cake when all you may need is a slice.

You can use Markers in logback to filter in a non-hierarchical way.

2) API's that encourage excessive String manipulation before the call is even made to see if the data is needed or not.

Again the slf4j/logback apis offer people the ("a {} b", foo) approach which addresses this.

I'll admit there is an advance to be made in this area if you took a lambda to produce your string.  In Java 8 you'd end up with something like:

logger.debug(() -> /* expensive string creation goes here */ )

the implementation of which can just delegate to level checking:

public void debug(Supplier<String> message) {

    if (isDebugEnabled()) {

        debug(message.get());

    }

}

3) XML configuration files ( this just is so wrong on so many levels....)

JUL lets you use properties, Logback lets you use groovy and you can do programmatic configuration in either of those two or log4j.

regards,

  Dr. Richard Warburton

  http://insightfullogic.com

  @RichardWarburto

[Jakub Kubrynski]

RIchard,

as I understand Kirk was writing about Chronicle :)

Kind regards,

Kuba

[Richard Warburton]

Hi Markus,

just my 2c here. I'm obviously coming from the higher level platform
(EE) here and the main issue I have is, that the described features
are _only_ available in 3rd party implementations.
What might be a simple packaging issue in SE starts to get really
messy with EE and server side components handling logging.
My aim would be to
a) make logging more pluggable or
b) define a more complete JUL ...

And standardising an area which already has plenty of 3rd party implementations is a good idea, and I'm not objecting to that.  On the contrary, I'm all for well thought through and battle-proven standards with active community participation.  I was specifically responding to the technical issues that Kirk raised, which were mostly valid issues a few years ago, but there really has been some progress in this area in the form of logback.

[Peter Lawrey]

Hello Kirk,

   The approach is a little different in the sense it is designed to make logging so cheap  to write and to read, you tend to write/read everything of interest (at least using tools to do this, because you will be writing more than a human can read)  It is left to the reader/filters to decide what is of interest.  The aim is to log everything to the point where you can recreate the exact state of the system (or in a multi-thread context, a close approximation)  This is useful for recovery, monitoring and diagnosis but is also the basis of any down stream system which needs data from your system i.e. it too can recreate the state of any upstream system it needs also. Your logging and messaging are combined.

To your points directly.

1) This forces you eat everything (or at least check some id which you can filter on so you don't have to read the whole message)  While this is worse in some ways you can read millions of messages per second this way without creating garbage (or creating very little depending on your needs)

2) When you write the message there is no String manipulation.  If there were, the API would be simpler I suspect but I avoid this because being gc-less is a priority for me.

3) There isn't any configuration, but you can piggy back on existing logging frameworks to turn on and off messages if you want, even if you don't use them to do the logging.  Given you can write lots of messages and data at low cost, you don't worry about this so much.

The performance numbers are for small messages to demonstrate the overhead of the framework which is much lower than the previous version.  I feel confident with this number because I am working on a pretty average laptop and I plan to test larger messages on a new over clocked i7-3970x with a PCI SSD and I am sure I can get that number with longer messages.  For longer messages you are dependant on the speed your CPU can copy fields so there is not much more that can be improved there.  (I have some ideas for raw copying of memory for objects which only contain primitives which should be faster)

The speed I am looking for should be comparable to the time it takes to clone the memory structure on the same hardware.  If I can do that, the cost of writing and reading messages is so low than many of the constraints we place of logging to minimise the performance hit go away.

Regards,

   Peter.

[Kirk Pepperdine]

>
>
> On 14 June 2013 09:09, Richard Warburton <richard....@gmail.com> wrote:
>> Hi,
>>
>>> I probably shouldn't be writing this email right now as I'm about to head
>>> out so that I can get home which means that I really can't layout the
>>> problems here in a meaningful way. But, I'll list what are IMHO the three
>>> biggest offences
>>
>>
>> I pretty much think all of these are solved, or semi-solved issues if you
>> look just a little below the surface.
>>
>>> 1) Hierarchical tag system that forces one to eat the entire layers of the
>>> cake when all you may need is a slice.
>>
>>
>> You can use Markers in logback to filter in a non-hierarchical way.

This is really a hack that doesn't address the fundamental problems.

>>
>>> 2) API's that encourage excessive String manipulation before the call is
>>> even made to see if the data is needed or not.
>>
>>
>> Again the slf4j/logback apis offer people the ("a {} b", foo) approach which
>> addresses this.

Ok, you get Object[] instead... the API is still messy.

Lambda's will help...

>>
>>> 3) XML configuration files ( this just is so wrong on so many levels....)
>>
>>
>> JUL lets you use properties, Logback lets you use groovy and you can do
>> programmatic configuration in either of those two or log4j.

XML, property files, it all works out to about the same problems. You get people defining excessively long logging structures with no regard to their impact on log performance.

-- Kirk

[Kirk Pepperdine]

Hi Richard,

Sorry but to suggest that my concerns are years old is a bit presumptuous. I have looked seriously at logback and I didn't feel that they'd addressed any of my concerns.

-- Kirk