Logging is blocking?

[Sascha Möllering]

Hi all,

yesterday we realized that extensive logging is dramatically slowing down Vertx's performance (logging is blocking). Are there any recommendations regarding logging (frameworks etc.)?

Thanks and Regards,

Sascha

[Ryan Chazen]

The logger built into vert.x is the normal java blocking logger - definitely a lot of room for improvement there. Hopefully it gets fully replaced in a future version?

I think if you want good logging speed for now, you could just make sure the current logfile is being written to a ramdisk which should help speed things up a bit (but it would still have the potential to block...)
Alternatively you probably can't go wrong with Log4j2's async loggers: http://logging.apache.org/log4j/2.x/manual/async.html

[Mumuney Abdlquadri]

I have not come across this. May be someone else will chime in.

But...
I guess you can create a separate module for logging specifically. Any
other module that needs logging will just send a message to the logger
module. So your main app will retain its performance. This is hacky I
know. Just a workaround.

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

[Sascha Möllering]

Hi,

thx, we'll take a look at this.

Regards,

Sascha

[Sascha Möllering]

We already thought about a similar solution with a dedicated WorkerVerticle for Logging, but IMHO that's not the way to got, because it will increase the load on the EventBus and we want to avoid that.

[Tim Fox]

Fundamentally heavy logging will limit the performance of a system in steady state whether or not it is blocking is not relevant.

If you generate X logging records per second then you still have to write out X logging records per second otherwise they will build up in the queue and you will eventually OOM.

Making logging asynchronous doesn't really help you here.

[Norman Maurer]

I kind of like the idea.. I guess it would be even possible to implement a Logger that just forward the events over the eventbus and then a user could register for the events and handle them if needed.

-- 
Norman Maurer

[Tim Fox]

On 07/01/14 09:36, Mumuney Abdlquadri wrote:
> I have not come across this. May be someone else will chime in.
>
> But...
> I guess you can create a separate module for logging specifically. Any
> other module that needs logging will just send a message to the logger
> module. So your main app will retain its performance.

Your main app might retain its performance but its just pushing the
problem elsewhere. Fundamentally whatever does the logging needs to be
able to persist to disk faster than it receives messages otherwise
messages will build up in memory and eventually fall out of RAM at which
point the application will fail.

> This is hacky I
> know. Just a workaround.
>

> On Tue, Jan 7, 2014 at 9:18 AM, Sascha M�llering

[Ryan Chazen]

Hey Tim,

It's true that you eventually have to flush the log events to the disk, but the difference between sync and async logging is the average time per log event is much lower with async because the disk writes can be batched.

You can check out this table for the kind of speed difference between the async log4j2 and sync log4j2 handlers: http://logging.apache.org/log4j/2.x/images/async-vs-sync-throughput.png

So I think there is a lot of benefit to be had from async logging in the same way we get benefit from async file writes...

--
You received this message because you are subscribed to a topic in the Google Groups "vert.x" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/vertx/9lzzZ5Ns9pk/unsubscribe.
To unsubscribe from this group and all of its topics, send an email to vertx+un...@googlegroups.com.

[Tim Fox]

On 07/01/14 09:55, Ryan Chazen wrote:

Hey Tim,

It's true that you eventually have to flush the log events to the disk, but the difference between sync and async logging is the average time per log event is much lower with async because the disk writes can be batched.

AIUI they are batched anyway with most logging frameworks, it's only if you do an explicit flush will they be flushed to disk, and even then they are just written to the OS which by default (in most OS setups) just writes to a cache and flushes asynchronously anyway

[Ryan Chazen]

While that's true, I recommend doing the following:
Make a simple program and use a standard java logger to log out a couple lines. Put a breakpoint on one of the log lines and see just how much work each log line is doing. It literally does as much work as netty/vertx does in handling an http request...

Also, OutputStreamWriter.flush() is explicitly called on every log line...

[Tim Fox]

I don't really get it.. according to the docs for standard FileAppender http://logging.apache.org/log4j/2.x/manual/appenders.html it can be configured to buffer and not flush on each write. IIRC this is the default anyway, so this is effectively async *anyway*, so no idea why they need a specific async file appender (what's the difference?)

But in any case, the file appender that you chose with log4j, whether async or not, can be changed by just editing the log4j configuration, and don't see that anything needs to be done in Vert.x at all.

[Ryan Chazen]

From http://vertx.io/manual.html#logging :

By default JUL logging is used. This can be configured using the file $VERTX_HOME\conf\logging.properties. Where VERTX_HOME is the directory in which you installed Vert.x.

So I was under the wrong(?) impression that the default was standard and very slow java logging. It does seem to be using standard java logging for me here, or at least the debugger I'm using is tracing through those classes... If that is the default, I think it should be changed to log4j2 because that's probably what most people want without realizing it.

[Tim Fox]

I meant the default for log4j is to buffer anyway :)

Yes the default logging framework for vert.x is JUL, but changing that is just config.

[Tim Fox]

On 07/01/14 10:31, Ryan Chazen wrote:

From http://vertx.io/manual.html#logging :

By default JUL logging is used. This can be configured using the file $VERTX_HOME\conf\logging.properties. Where VERTX_HOME is the directory in which you installed Vert.x.

So I was under the wrong(?) impression that the default was standard and very slow java logging. It does seem to be using standard java logging for me here, or at least the debugger I'm using is tracing through those classes... If that is the default, I think it should be changed to log4j2 because that's probably what most people want without realizing it.

We could make log4j the default, the main (only?) reason why we don't is to keep the distro small and not introduce another jar dependency....

[Ryan Chazen]

I'd think you'd either end up with a guide "Things to do before putting vert.x into production" with an entry for "change the logging framework", or you'd just have vert.x default to settings that work in production. I'd prefer the 2nd option - if everyone running vert.x has to go and configure the logging params and get log4j2 etc, then it's just made it more complicated and they end up with the jar dependency anyway. And if they don't know, then they get half the expected performance because their logging is using up all the processing...

Seems both cases are pretty bad: either people don't change the default and get bad performance, or they have to go and download the jar anyway which is more work than having it be part of vert.x from the start?

[Norman Maurer]

I wonder why the logging is affecting stuff so much… Are we logging so many things by default, I thought we only do when debug is set ?

-- 
Norman Maurer

[Tim Fox]

Vert.x logs hardly anything, this is user logging

[Sascha Möllering]

It's our logging, well, kind of ... the Kafka-driver is logging like crazy.

[Norman Maurer]

Well I would argue it’s an „user issue“ then as the user should only log large amount of stuff when in debug level.  

-- 
Norman Maurer

[Norman Maurer]

Hey Sascha,

Can’t you setup logging.properties to adjust the log level for it ?

-- 
Norman Maurer

[Sascha Möllering]

Hey Norman,

sure of course, we already did that, it was more a general question concerning logging and performance.

Thx,

Sascha

[Tim Fox]

On 07/01/14 11:44, Sascha Möllering wrote:

Hey Norman,

sure of course, we already did that, it was more a general question concerning logging and performance.

I'd definitely recommend using log4j instead of JUL

[Tom Carchrae]

Perhaps this is well known, but I'll mention it because I've seen it happen many times:  Make sure your logging statements use as little resources as possible.   Eg

   logger.debug("this is bad news" + objectWithAnExpensiveToString);

as is

   logger.debug("this is bad news : %s ", expensiveComputation());

what you probably should do - especially around expensive debugs or any hotspots/performance bottlenecks parts of your code

 if (logger.isDebugEnabled()) logger.debug("heeeeey, relax - this is an unloaded dev machine " + generateSomeBitcoins());

and in general always use the string format (logger.debug("value is %d",value); ) and never string concat logger.debug("hey" + thing) since AFAIK, the JVM cannot optimize out the string concat before it invokes logger.debug.

Hope that is helpful,

Tom

[Tim Fox]

+1

On 07/01/14 14:27, Tom Carchrae wrote:

Perhaps this is well known, but I'll mention it because I've seen it happen many times: �Make sure your logging statements use as little resources as possible. � Eg

� �logger.debug("this is bad news" + objectWithAnExpensiveToString);

as is

� �logger.debug("this is bad news : %s ", expensiveComputation());

what you probably should do - especially around expensive debugs or any hotspots/performance bottlenecks parts of your code

�if (logger.isDebugEnabled()) logger.debug("heeeeey, relax - this is an unloaded dev machine " + generateSomeBitcoins());

and in general always use the string format (logger.debug("value is %d",value); ) and never string concat logger.debug("hey" + thing) since AFAIK, the JVM cannot optimize out the string concat before it invokes logger.debug.

Hope that is helpful,

Tom

On Tue, Jan 7, 2014 at 3:46 AM, Tim Fox <timv...@gmail.com> wrote:

On 07/01/14 11:44, Sascha M�llering wrote:

Hey Norman,

sure of course, we already did that, it was more a general question concerning logging and performance.

I'd definitely recommend using log4j instead of JUL

Thx,

Sascha

Am Dienstag, 7. Januar 2014 12:42:16 UTC+1 schrieb Norman Maurer:

Hey Sascha,

Can�t you setup logging.properties to adjust the log level for it ?

--�
Norman Maurer

An 7. Januar 2014 at 12:40:47, Sascha M�llering (sascha.m...@gmail.com) schrieb:

It's our logging, well, kind of ... the Kafka-driver is logging like crazy.

Am Dienstag, 7. Januar 2014 12:37:08 UTC+1 schrieb Norman Maurer:

I wonder why the logging is affecting stuff so much� Are we logging so many things by default, I thought we only do when debug is set ?

--�
Norman Maurer

An 7. Januar 2014 at 11:37:17, Tim Fox (timv...@gmail.com) schrieb:

On 07/01/14 10:31, Ryan Chazen wrote:

From http://vertx.io/manual.html#logging :

By default JUL logging is used. This can be configured using the file $VERTX_HOME\conf\logging.properties. Where VERTX_HOME is the directory in which you installed Vert.x.

So I was under the wrong(?) impression that the default was standard and very slow java logging. It does seem to be using standard java logging for me here, or at least the debugger I'm using is tracing through those classes... If that is the default, I think it should be changed to log4j2 because that's probably what most people want without realizing it.

We could make log4j the default, the main (only?) reason why we don't is to keep the distro small and not introduce another jar dependency....

On Tue, Jan 7, 2014 at 12:24 PM, Tim Fox <timv...@gmail.com> wrote:

I don't really get it.. according to the docs for standard FileAppender http://logging.apache.org/log4j/2.x/manual/appenders.html it can be configured to buffer and not flush on each write. IIRC this is the default anyway, so this is effectively async *anyway*, so no idea why they need a specific async file appender (what's the difference?)

But in any case, the file appender that you chose with log4j, whether async or not, can be changed by just editing the log4j configuration, and don't see that anything needs to be done in Vert.x at all.

On 07/01/14 10:19, Ryan Chazen wrote:

While that's true, I recommend doing the following:
Make a simple program and use a standard java logger to log out a couple lines. Put a breakpoint on one of the log lines and see just how much work each log line is doing. It literally does as much work as netty/vertx does in handling an http request...

Also, OutputStreamWriter.flush() is explicitly called on every log line...

On Tue, Jan 7, 2014 at 12:09 PM, Tim Fox <timv...@gmail.com> wrote:

On 07/01/14 09:55, Ryan Chazen wrote:

Hey Tim,

It's true that you eventually have to flush the log events to the disk, but the difference between sync and async logging is the average time per log event is much lower with async because the disk writes can be batched.

AIUI they are batched anyway with most logging frameworks, it's only if you do an explicit flush will they be flushed to disk, and even then they are just written to the OS which by default (in most OS setups) just writes to a cache and flushes asynchronously anyway

You can check out this table for the kind of speed difference between the async log4j2 and sync log4j2 handlers: http://logging.apache.org/log4j/2.x/images/async-vs-sync-throughput.png

So I think there is a lot of benefit to be had from async logging in the same way we get benefit from async file writes...

On Tue, Jan 7, 2014 at 11:49 AM, Norman Maurer <norman...@googlemail.com> wrote:

I kind of like the idea.. I guess it would be even possible to implement a Logger that just forward the events over the eventbus and then a user could register for the events and handle them if needed.

--�
Norman Maurer

An 7. Januar 2014 at 10:36:31, Mumuney Abdlquadri (abdlq...@googlemail.com) schrieb:

I have not come across this. May be someone else will chime in.

But...
I guess you can create a separate module for logging specifically. Any
other module that needs logging will just send a message to the logger
module. So your main app will retain its performance. This is hacky I
know. Just a workaround.

On Tue, Jan 7, 2014 at 9:18 AM, Sascha M�llering

[Brice Dutheil]

What about JavaChronicle, Peter Lawrey did something fantastic there.

https://github.com/peter-lawrey/Java-Chronicle

-- Brice

On Tue, Jan 7, 2014 at 3:28 PM, Tim Fox <timv...@gmail.com> wrote:

+1

On 07/01/14 14:27, Tom Carchrae wrote:

Perhaps this is well known, but I'll mention it because I've seen it happen many times:  Make sure your logging statements use as little resources as possible.   Eg

   logger.debug("this is bad news" + objectWithAnExpensiveToString);

as is

   logger.debug("this is bad news : %s ", expensiveComputation());

what you probably should do - especially around expensive debugs or any hotspots/performance bottlenecks parts of your code

 if (logger.isDebugEnabled()) logger.debug("heeeeey, relax - this is an unloaded dev machine " + generateSomeBitcoins());

and in general always use the string format (logger.debug("value is %d",value); ) and never string concat logger.debug("hey" + thing) since AFAIK, the JVM cannot optimize out the string concat before it invokes logger.debug.

Hope that is helpful,

Tom

On Tue, Jan 7, 2014 at 3:46 AM, Tim Fox <timv...@gmail.com> wrote:

On 07/01/14 11:44, Sascha Möllering wrote:

Hey Norman,

sure of course, we already did that, it was more a general question concerning logging and performance.

I'd definitely recommend using log4j instead of JUL

Thx,

Sascha

Am Dienstag, 7. Januar 2014 12:42:16 UTC+1 schrieb Norman Maurer:

Hey Sascha,

Can’t you setup logging.properties to adjust the log level for it ?

-- 
Norman Maurer

An 7. Januar 2014 at 12:40:47, Sascha Möllering (sascha.m...@gmail.com) schrieb:

It's our logging, well, kind of ... the Kafka-driver is logging like crazy.

Am Dienstag, 7. Januar 2014 12:37:08 UTC+1 schrieb Norman Maurer:

I wonder why the logging is affecting stuff so much… Are we logging so many things by default, I thought we only do when debug is set ?

-- 
Norman Maurer

An 7. Januar 2014 at 11:37:17, Tim Fox (timv...@gmail.com) schrieb:

On 07/01/14 10:31, Ryan Chazen wrote:

From http://vertx.io/manual.html#logging :

By default JUL logging is used. This can be configured using the file $VERTX_HOME\conf\logging.properties. Where VERTX_HOME is the directory in which you installed Vert.x.

So I was under the wrong(?) impression that the default was standard and very slow java logging. It does seem to be using standard java logging for me here, or at least the debugger I'm using is tracing through those classes... If that is the default, I think it should be changed to log4j2 because that's probably what most people want without realizing it.

We could make log4j the default, the main (only?) reason why we don't is to keep the distro small and not introduce another jar dependency....

On Tue, Jan 7, 2014 at 12:24 PM, Tim Fox <timv...@gmail.com> wrote:

I don't really get it.. according to the docs for standard FileAppender http://logging.apache.org/log4j/2.x/manual/appenders.html it can be configured to buffer and not flush on each write. IIRC this is the default anyway, so this is effectively async *anyway*, so no idea why they need a specific async file appender (what's the difference?)

But in any case, the file appender that you chose with log4j, whether async or not, can be changed by just editing the log4j configuration, and don't see that anything needs to be done in Vert.x at all.

On 07/01/14 10:19, Ryan Chazen wrote:

While that's true, I recommend doing the following:
Make a simple program and use a standard java logger to log out a couple lines. Put a breakpoint on one of the log lines and see just how much work each log line is doing. It literally does as much work as netty/vertx does in handling an http request...

Also, OutputStreamWriter.flush() is explicitly called on every log line...

On Tue, Jan 7, 2014 at 12:09 PM, Tim Fox <timv...@gmail.com> wrote:

On 07/01/14 09:55, Ryan Chazen wrote:

Hey Tim,

It's true that you eventually have to flush the log events to the disk, but the difference between sync and async logging is the average time per log event is much lower with async because the disk writes can be batched.

AIUI they are batched anyway with most logging frameworks, it's only if you do an explicit flush will they be flushed to disk, and even then they are just written to the OS which by default (in most OS setups) just writes to a cache and flushes asynchronously anyway

You can check out this table for the kind of speed difference between the async log4j2 and sync log4j2 handlers: http://logging.apache.org/log4j/2.x/images/async-vs-sync-throughput.png

So I think there is a lot of benefit to be had from async logging in the same way we get benefit from async file writes...

On Tue, Jan 7, 2014 at 11:49 AM, Norman Maurer <norman...@googlemail.com> wrote:

I kind of like the idea.. I guess it would be even possible to implement a Logger that just forward the events over the eventbus and then a user could register for the events and handle them if needed.

-- 
Norman Maurer

An 7. Januar 2014 at 10:36:31, Mumuney Abdlquadri (abdlq...@googlemail.com) schrieb:

I have not come across this. May be someone else will chime in.

But...
I guess you can create a separate module for logging specifically. Any
other module that needs logging will just send a message to the logger
module. So your main app will retain its performance. This is hacky I
know. Just a workaround.

On Tue, Jan 7, 2014 at 9:18 AM, Sascha Möllering

[maurycy szmurlo]

Hi,

What about logging to syslog on another server ? Syslog takes care of log management, eg rotation, and if nevertheless something happen like a out of ram or crash, vertx app will not be affected (except it will lose the logs for a while)

Still, formatting the log message will require anyway some CPU...

Maurice

[Brice Dutheil]

Syslog is not available on windows, I believe.

Still it could be another configuration.

--

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

--

-- Brice