new log library?

[shah...@gmail.com]

Martin's mentioned a few times that he is planning on releasing a fast logging library soon. Any idea when that might be?

We are switching from log4j and I'd love to take a look at Martin's lib.

[Martin Thompson]

This is not likely to be available until later this year.

[Peter Lawrey]

You might consider Java Chronicle.

It can log text at a rate of between 100K to 1,000K lines per second (GC free)

It can log binary entries at a rate well over one million per second (also GC free)

It is *not* a drop in replacement for log4j though.

Peter.

On 18 April 2013 18:09, <shah...@gmail.com> wrote:

Martin's mentioned a few times that he is planning on releasing a fast logging library soon. Any idea when that might be?

We are switching from log4j and I'd love to take a look at Martin's lib.

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

[shah...@gmail.com]

I've been meaning to check it out. Thanks.

On Thursday, April 18, 2013 2:18:21 PM UTC-4, Peter Lawrey wrote:

You might consider Java Chronicle.

It can log text at a rate of between 100K to 1,000K lines per second (GC free)

It can log binary entries at a rate well over one million per second (also GC free)

It is *not* a drop in replacement for log4j though.

Peter.

On 18 April 2013 18:09, <shah...@gmail.com> wrote:

Martin's mentioned a few times that he is planning on releasing a fast logging library soon. Any idea when that might be?

We are switching from log4j and I'd love to take a look at Martin's lib.

--
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-sympathy+unsub...@googlegroups.com.

[Martin Thompson]

Peter do you support multiple concurrent producers yet?

Any better logging implementation will not be an API drop in replacement for Log4J ;-)

[Peter Lawrey]

It supports multiple producer threads provided they use locking, 

When writing binary data, this is usually faster than the disk subsystem can cope with.

--

[Martin Thompson]

It is easy to overcome most disk systems on throughput.  The big issue with locks comes from the variable latency when they occasionally become contended. 

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

[Peter Lawrey]

I agree, which is why I suggest a busy waiting, bound to a CPU/core, single threaded producer without a lock if possible.

When dealing with external systems or third party libraries it is not always possible in which case using a lock may be a simple/pragmatic choice.  

The cost of the lock is usually less than what the network IO, or a third party library will be doing to your system/latency.

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

[Martin Thompson]

On Friday, April 19, 2013 9:48:43 AM UTC+1, Peter Lawrey wrote:

The cost of the lock is usually less than what the network IO, or a third party library will be doing to your system/latency.

This is not always true.  Without setting affinity I see the cost of a contended lock and associated context switch to be ~10us or greater on Linux.  Can be down to ~3us on a well tuned system.  

Now if you consider using 10GigE with kernel bypass libraries (Solarflare, Mellanox, or RoCE directly) the cost of a full network hop can be under 3us.  If you are on a crappy older, or not well setup network, then the balance is greatly reversed.

I'm just illustrating this point because I know it is possible to write a multi-producer scenario that does not use locks and has other benefits.  I believe a good logging framework should from the producers perspective be lock-free, wait-free, copy-free and garbage-free.  Any logging approach that is greater than or equal to the cost of a network hop has a lot of room for improvement.  A write to java.util.logging can cost 16us in the *uncontended* case which is shocking.

I'm not knocking Chronicle which I think is a great library.  I think it is at its best when used from a single-threaded producer.  Many applications have multiple producers utilising a shared logging infrastructure.  Mechanical Sympathy for me is working in harmony with infrastructure to get the best out of it.  I think as an industry we should talk more openly about what design patterns and infrastructure work best together.

Martin... 

[Peter Lawrey]

While I agree the numbers, it's not entirely fair to compare contented/non ideal latency of one thing with the best case numbers of another.

In my experience, the worst case numbers of real networks tend to be higher than the worst case numbers of locking even if both are well engineered.

I would have thought a write to Java logging with dates and doubles etc can be much higher than 16 us esp as they create quite a bit of garbage. ;)

>  I think it is at its best when used from a single threaded producer.

I totally agree.  Locking is only a solution if something more sophisticated is hard to justify.

On 19 April 2013 10:10, Martin Thompson <mjp...@gmail.com> wrote:

On Friday, April 19, 2013 9:48:43 AM UTC+1, Peter Lawrey wrote:

The cost of the lock is usually less than what the network IO, or a third party library will be doing to your system/latency.

This is not always true.  Without setting affinity I see the cost of a contended lock and associated context switch to be ~10us or greater on Linux.  Can be down to ~3us on a well tuned system.  

Now if you consider using 10GigE with kernel bypass libraries (Solarflare, Mellanox, or RoCE directly) the cost of a full network hop can be under 3us.  If you are on a crappy older, or not well setup network, then the balance is greatly reversed.

I'm just illustrating this point because I know it is possible to write a multi-producer scenario that does not use locks and has other benefits.  I believe a good logging framework should from the producers perspective be lock-free, wait-free, copy-free and garbage-free.  Any logging approach that is greater than or equal to the cost of a network hop has a lot of room for improvement.  An write to java.util.logging can cost 16us in the *uncontended* case which is unbelievable.

I'm not knocking Chronicle which I think is a great library.  I think it is at its best when used from a single threaded producer.  Many applications have multiple producers requiring a shared logging infrastructure.  Mechanical Sympathy for me is working in harmony with infrastructure to get the best out of it.  I think as an industry we should talk more openly about what design patterns and infrastructure work best together.

Martin... 

--

[Martin Thompson]

On Friday, April 19, 2013 11:52:34 AM UTC+1, Peter Lawrey wrote:

While I agree the numbers, it's not entirely fair to compare contented/non ideal latency of one thing with the best case numbers of another.

In my experience, the worst case numbers of real networks tend to be higher than the worst case numbers of locking even if both are well engineered.

Depends on the network and OS.  I quoted a like-for-like with averages.  Worst case on contended locks and network hops can be similar if the network hop is local area.  TCP can be much harder to get right than UDP or IP Multicast.  If the lock turns out to not be contended then it is fairly cheap.

The main thing we want to strive for is consistent latency and in both cases a well tuned OS is important otherwise the background noise is too significant.  For example I've seen an OS lock up for seconds under too much virtual memory pressure or compacting the heap for transparent large pages. 

I would have thought a write to Java logging with dates and doubles etc can be much higher than 16 us esp as they create quite a bit of garbage. ;)

This is just for logging a simple 50 byte String with no concatenation or parameters to substitute! 

[Jean-Philippe BEMPEL]

Talking about that I have seen this: 
http://techblog.netflix.com/2012/11/announcing-bitz4j-scalable-logging.html

never tried.

Jean-Philippe

[Peter Lawrey]

It looks good 1-3 microseconds, but 300-500 lines per second doesn't sound that high.

--

[Martin Thompson]

Peter is right on this.  I've seen implementations make 15-25m events per second at a few 10s of nanoseconds latency impact on the write side.  I'm sure logging into Chronicle is in the ballpark.

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

[Peter Lawrey]

For text, is a few 100s nano-seconds. 

For binary around 100 ns for a short message/line/excerpt.

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

[John Gu]

Hi Martin, Peter,

Thanks for a very informative thread.  

Martin, you mentioned the a optimal logging framework from the producer's side would be lock-free, wait-free, copy-free, and garbage-free.  Can you elaborate a bit on what the design might look like?  One design that I've played around with is using disruptor as a message queue, and putting logging messages into disruptor for another thread to handle.  However, this has the restriction that logging messages cannot contain reference to mutable objects, which involves first copying these objects somehow.

While I haven't taken an in-depth look at Peter's library, I believe the approach it uses is to have the producer be responsible for serializing objects into some binary format into a memory mapped file (using ByteBuffers or Unsafe approaches).  Would you consider this a copy?  Using Peter's library also involves some work on the client side for objects to know how they should be encoded, but I really don't see how you can get around this.  I can imagine extending Peter's approach by having Excerpts reserve a certain chunk of memory from the Chronicle.  This reservation process would be an atomic read-and-increment of a pointer into memory that is free.  Once the reservation happens, the Excerpt is free to write what it wants into its reserved space.  This would get around the need for locking.

Anyhow, would be curious to get your views, and some views of what a high level design to efficient logging would look like.

Thanks,

John

[Martin Thompson]

On Friday, April 19, 2013 6:43:21 PM UTC+1, John Gu wrote:

Martin, you mentioned the a optimal logging framework from the producer's side would be lock-free, wait-free, copy-free, and garbage-free.  Can you elaborate a bit on what the design might look like?  One design that I've played around with is using disruptor as a message queue, and putting logging messages into disruptor for another thread to handle.  However, this has the restriction that logging messages cannot contain reference to mutable objects, which involves first copying these objects somehow.

I believe a logging library should allow the recording of semantically rich messages.  This means structures/objects and not strings.  The API should be simple in that you just log an object via an interface method which is much better for testing than a static method.  This object/event to be recorded, which can be a graph, can then be serialised to shared memory buffer using an efficient binary format.  The code to do the serialisation can be generated bytecode and use Unsafe for C like performance.  Regions of the shared memory buffer can be claimed using a lock-free algorithm and thus requires no additional buffer copy or serialisation.  This needs to happen on the calling thread so that further object mutation can occur without requiring an object copy.  Separate threads can be used to archive the shared memory to disk or a remote storage server.   I've taken similar approaches that can record over 20m events per second concurrently at ~25ns latency from many producing threads.  I consider the thread recording an event to be a producer.

A major benefit to using a shared memory buffer is that in the event of your process crashing the log is not lost.  This is really important because the events recorded just before a crash are often the most useful to debugging that crash.

[Peter Lawrey]

Hello John,

   Your suggestion of using an atomic increment could work, thought there are a number of data structures which assume single threaded-ness e.g. the growing of the index and data files.  

If you have a SATA SSD, I can assure you that one thread on a half decent can saturate the bandwidth to such a drive.  I haven't tested with a PCI SSD, but I believe you should get pretty close to the maximum write speed of such a device with just one thread. i.e. having only one thread writing at a time, your bottleneck is likely to be your hardware.

   Even writing text, you can write about 1.5 GB/s to tmpfs on a fast machine. For a fast PCI x2 SSD this is more than enough http://ocz.com/consumer/revodrive-3-x2-pcie-ssd ~£1.2K rated to 1.3 GB/s.  However there are PCI x4 SSD cards which can do more http://hothardware.com/Reviews/OCZ-ZDrive-R4-Performance-Preview/ ~ £7.4K rated to 2.8 GB/s

Regards,

   Peter.

--

[Peter Lawrey]

> A major benefit to using a shared memory buffer is that in the event of your process crashing the log is not lost.  This is really important because the events recorded just before a crash are often the most useful to debugging that crash.

I suggest using Unsafe to check this is true.  You can write a message and crash the JVM with Unsafe access to say address 0.  This kills the whole JVM almost immediately (faster than pulling the power out of the machine) and no shutdown tasks are performed.

BTW If you pull the power out of the machine this takes in the order of 0.016 seconds (at 60 Hz) to 0.1 seconds (with some capacitance) for the machine to die.

--

[Martin Thompson]

On Saturday, April 20, 2013 10:16:17 AM UTC+1, Peter Lawrey wrote:

> A major benefit to using a shared memory buffer is that in the event of your process crashing the log is not lost.  This is really important because the events recorded just before a crash are often the most useful to debugging that crash.

I suggest using Unsafe to check this is true.  You can write a message and crash the JVM with Unsafe access to say address 0.  This kills the whole JVM almost immediately (faster than pulling the power out of the machine) and no shutdown tasks are performed.

BTW If you pull the power out of the machine this takes in the order of 0.016 seconds (at 60 Hz) to 0.1 seconds (with some capacitance) for the machine to die.

Interesting point.  I'll have a play with that. 

[Peter Lawrey]

I use the following

        // perform some action

        UNSAFE.putLong(0,0); // Seg-fault.

After it has died, check the action was performed.

--

[bra...@gmail.com]

Not sure if anyone has looked at Log4j2:

http://logging.apache.org/log4j/2.x/manual/async.html

I currently use Logback and experience quite a bit of contention due to the relatively course locking it employs. Log4j2 is still in beta, but looks quite promising. I believe it uses the Disrupter library internally to provide asynchronous logging for producers threads.

[Remko Popma]

Martin,

Would you be interested in having this be part of log4j? I don't know what API you have in mind, but log4j 2.0 is currently in beta, and changes are still possible. We'd love your input.

Respectfully,
Remko Popma
rpo...@apache.org

[Martin Thompson]

Remko,

My views on what makes a good logging library are a very radical departure from the likes of log4j.  I'm not saying log4j is wrong, it is just that it does not fit the requirements I see in the various clients I work with.  

Are you suggesting that with the new version you are considering moving away from static methods and logging strings as a standard API?  I think the standard log4j API can be preserved and the performance greatly improved, however this API places serious limitations on performance, semantics, and testability.

My instincts are to produce a new journalling/logging library that meets the requirements of those at the high-end of performance without compromise.  These folk are almost always rolling their own anyway.  Then produce adapters/facades for the standard logging APIs for compatibility.  This would allow a gradual migration of an existing code base and support the use of 3rd party libraries.   A compromise solution will leave everyone equally dissatisfied.

Martin...

[Kirk Pepperdine]

On 2013-05-07, at 11:10 AM, Martin Thompson <mjp...@gmail.com> wrote:

> Remko,
>
> My views on what makes a good logging library are a very radical departure from the likes of log4j.

+1

> I'm not saying log4j is wrong, it is just that it does not fit the requirements I see in the various clients I work with.

Martin, I'll happily say it and all of it's ilk are wrong from an API perspective. LogBack, JDK logging, SLF4J... all suffer from the same problems.

>
> Are you suggesting that with the new version you are considering moving away from static methods and logging strings as a standard API? I think the standard log4j API can be preserved and the performance greatly improved, however this API places serious limitations on performance, semantics, and testability.

Forced string concatenation being one of the biggest.

>
> My instincts are to produce a new journalling/logging library that meets the requirements of those at the high-end of performance without compromise. These folk are almost always rolling their own anyway. Then produce adapters/facades for the standard logging APIs for compatibility. This would allow a gradual migration of an existing code base and support the use of 3rd party libraries. A compromise solution will leave everyone equally dissatisfied.

IME, a high-end performance logging framework would meet most people's purposes far more than a compromise would. BTW, JEP 148 is suppose to introduce a log4j like framework into the JVM... I'm hoping it dies on the vine!!! In the mean time there are people interested in building a new completely different logging framework.

-- Kirk

[Remko Popma]

On Tuesday, May 7, 2013 6:10:16 PM UTC+9, Martin Thompson wrote:

Remko,

My views on what makes a good logging library are a very radical departure from the likes of log4j.  I'm not saying log4j is wrong, it is just that it does not fit the requirements I see in the various clients I work with.  

Are you suggesting that with the new version you are considering moving away from static methods and logging strings as a standard API?  I think the standard log4j API can be preserved and the performance greatly improved, however this API places serious limitations on performance, semantics, and testability.

Yes, certainly moving in that direction.

In 2.0, Loggers are now interfaces that log Message objects.  When obtaining a Logger you can specify a MessageFactory. 

One very direct way to implement the ideas you mentioned earlier in this thread would be to have a custom MessageFactory implementation that claims a region of a shared memory buffer and serializes the parameter object(s) into the buffer.  It could return a null Message object and the remainder of the downstream Logger call could be an empty implementation.  You would not have the Level information in the log, but filtering events below a certain Level threshold would still work.

The hardest part as far as I can see is the serialization.  (That is kind of assuming that you already have an off-heap ringbuffer implementation in your back pocket... :-)

My instincts are to produce a new journalling/logging library that meets the requirements of those at the high-end of performance without compromise.  These folk are almost always rolling their own anyway.  Then produce adapters/facades for the standard logging APIs for compatibility.  This would allow a gradual migration of an existing code base and support the use of 3rd party libraries.   A compromise solution will leave everyone equally dissatisfied.

I fully understand that you don't want to be held back by the limitations of a legacy API.  Definitely don't compromise on performance!  I agree that this would not make anybody happy.  I'm open to any feedback or recommendation in terms of API or otherwise.  Don't hesitate to let me know if we can help/collaborate in any way, and I certainly look forward to the result.

-Remko