You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by "Remko Popma (JIRA)" <ji...@apache.org> on 2013/02/07 06:53:14 UTC

[jira] [Comment Edited] (LOG4J2-163) Create asynchronous Logger for low-latency logging

    [ https://issues.apache.org/jira/browse/LOG4J2-163?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13573221#comment-13573221 ] 

Remko Popma edited comment on LOG4J2-163 at 2/7/13 5:52 AM:
------------------------------------------------------------

AsyncLoggerConfig, nice idea, I like it!

I can see several advantages:
* ability to use synchronous and asynchronous logging at the same time
* can control usage in the configuration file, instead of the (rather clumsy) system property -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector that I was using up to now
* same for clock implementation and ring buffer size, can be controlled in the config file
* potentially use config to switch on/off whether location is required with async logging (LOG4J2-153)

I don't see any issues with async logger delegating to sync parent loggers, am I missing something?
(the way I envision the implementation) the call to LoggerConfig.log(LogEvent) would be in the I/O thread, initiated by the RingBufferLogEventHandler. Then this is simply a case of multiple threads calling LoggerConfig.log(LogEvent) simultaneously, which Log4j already handles...

About performance impact, are you referring to the current implementation of core.Logger.log(Marker, String, Level, Message, Throwable), specifically, the call to configurationMonitor.checkConfiguration()?

It is crucial for performance to keep all I/O in the I/O thread, but I think that with a bit of indirection we can achieve both goals:
1. before writing a message to disk, always check first if config has changed and if it has changed, use the new config
2. in async loggers, all disk access (incl config check) is done in the I/O thread

The indirection would work as follows:

Logger:
public void log(Marker marker, String fqcn, Level level, Message data, Throwable t) {
    config.loggerConfig.beforeLog(this, marker, fqcn, level, data, t);
}

public void actualLog(Marker marker, String fqcn, Level level, Message data, Throwable t) {
    config.loggerConfig.log(getName(), marker, fqcn, level, data, t);
}

public void actualLog(LogEvent event) {
    config.loggerConfig.log(event);
}


(Sync)LoggerConfig:
public void beforeLog(Logger logger, Marker marker, String fqcn, Level level, Message data, Throwable t) {
    if (data == null) {
        data = new SimpleMessage("");
    }
    config.getConfigurationMonitor().checkConfiguration();
    // logger may now have a different config
    logger.actualLog(marker, fqcn, level, data, t);
}
public void log(String loggerName, Marker marker, String fqcn, Level level, Message data, Throwable t) {
    ... // current implementation unchanged
}

AsyncLoggerConfig:
public void beforeLog(Logger logger, Marker marker, String fqcn, Level level, Message data, Throwable t) {
    ... // put parameter values in RingBuffer, incl a reference to this AsyncLoggerConfig
    ... // (same logic as AsyncLogger.log)
}
// TODO change RingBufferLogEvent.execute to call AsyncLoggerConfig.actualAsyncLog

public void actualAsyncLog(RingBufferLogEvent event) {
    // this is executed in the I/O thread
    
    if (data == null) {
        data = new SimpleMessage("");
    }
    config.getConfigurationMonitor().checkConfiguration();
    // logger may now have a different config
    
    event.mergePropertiesIntoContextMap(getProperties(), 
            event.getLogger().getContext().getConfiguration().getSubst());
    event.getLogger().actualLog(event);
}



                
      was (Author: remkop@yahoo.com):
    AsyncLoggerConfig, nice idea, I like it!

I can see several advantages:
* ability to use synchronous and asynchronous logging at the same time
* can control usage in the configuration file, instead of the (rather clumsy) system property -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector that I was using up to now
* same for clock implementation and ring buffer size, can be controlled in the config file
* potentially use config to switch on/off whether location is required with async logging (LOG4J2-153)

I don't see any issues with async logger delegating to sync parent loggers, am I missing something?
(the way I envision the implementation) the call to LoggerConfig.log(LogEvent) would be in the I/O thread, initiated by the RingBufferLogEventHandler. Then this is simply a case of multiple threads calling LoggerConfig.log(LogEvent) simultaneously, which Log4j already handles...

About performance impact, are you referring to the current implementation of core.Logger.log(Marker, String, Level, Message, Throwable), specifically, the call to configurationMonitor.checkConfiguration()?

It is crucial for performance to keep all I/O in the I/O thread, but I think that with a bit of indirection we can achieve both goals:
1. before writing a message to disk, always check first if config has changed and if it has changed, use the new config
2. in async loggers, all disk access (incl config check) is done in the I/O thread

The indirection would work as follows:

Logger:
public void log(Marker marker, String fqcn, Level level, Message data, Throwable t) {
    config.loggerConfig.beforeLog(this, marker, fqcn, level, data, t);
}

public void actualLog(Marker marker, String fqcn, Level level, Message data, Throwable t) {
    config.loggerConfig.log(getName(), marker, fqcn, level, data, t);
}

public void actualLog(LogEvent event) {
    config.loggerConfig.log(event);
}


(Sync)LoggerConfig:
public void beforeLog(Logger logger, Marker marker, String fqcn, Level level, Message data, Throwable t) {
    if (data == null) {
        data = new SimpleMessage("");
    }
    config.getConfigurationMonitor().checkConfiguration();
    // logger may now have a different config
    logger.actualLog(marker, fqcn, level, data, t);
}
public void log(String loggerName, Marker marker, String fqcn, Level level, Message data, Throwable t) {
    ... // current implementation unchanged
}

AsyncLoggerConfig:
public void beforeLog(Logger logger, Marker marker, String fqcn, Level level, Message data, Throwable t) {
    ... // put parameter values in RingBuffer, incl 
    ... // (same logic as AsyncLogger.log)
}
// TODO change RingBufferLogEvent.execute to call AsyncLoggerConfig.actualAsyncLog

public void actualAsyncLog(RingBufferLogEvent event) {
    // this is executed in the I/O thread
    
    if (data == null) {
        data = new SimpleMessage("");
    }
    config.getConfigurationMonitor().checkConfiguration();
    // logger may now have a different config
    
    event.mergePropertiesIntoContextMap(getProperties(), 
            event.getLogger().getContext().getConfiguration().getSubst());
    event.getLogger().actualLog(event);
}



                  
> Create asynchronous Logger for low-latency logging
> --------------------------------------------------
>
>                 Key: LOG4J2-163
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-163
>             Project: Log4j 2
>          Issue Type: Improvement
>    Affects Versions: 2.0-beta4
>            Reporter: Remko Popma
>         Attachments: FastLog4j-v2-for-beta4.zip, FastLog4j-v3-for-beta4.zip
>
>
> One of the main considerations for selecting a logging library is performance, specifically, how long it takes for a call to Logger.log to return. (See the comments of LOG4J-151 for a discussion of latency versus application throughput and logging throughput.)
> I believe it is possible to improve this performance by an order of magnitude by having an asynchronous Logger implementation that hands off the work to a separate thread as early as possible. The disk I/O would be done in this separate thread. 
> AsynchAppender is not a good match for these requirements, as with that approach (a) the logging call still needs to flow down the hierarchy to the appender, doing synchronization and creating objects at various points on the way, and (b) when serializing the LogEvent, the getSource() method is always called, which is expensive.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org