Log4j 2
  1. Log4j 2
  2. LOG4J2-163

Create asynchronous Logger for low-latency logging

    Details

    • Type: Improvement Improvement
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-beta4
    • Fix Version/s: 2.0-beta5
    • Component/s: None
    • Labels:
      None

      Description

      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.

      1. FastLog4j-v2-for-beta4.zip
        226 kB
        Remko Popma
      2. FastLog4j-v3-for-beta4.zip
        236 kB
        Remko Popma
      3. FastLog4j-v4-for-beta4.zip
        269 kB
        Remko Popma
      4. LOG4J2-163-log4j-async.patch
        308 kB
        Remko Popma
      5. LOG4J2-163-log4j-async-20130320.patch
        434 kB
        Remko Popma
      6. async-perf-comparison.png
        61 kB
        Remko Popma
      7. LOG4J2-163-log4j-async-20130331.patch
        487 kB
        Remko Popma
      8. LOG4J2-163-log4j-async-20130331-images.zip
        187 kB
        Remko Popma
      9. LOG4J2-163-log4j-async-20130331a.patch
        277 kB
        Remko Popma

        Issue Links

          Activity

          Hide
          Remko Popma added a comment -

          v3 changes
          ----------

          • Added performance tests for multi-threaded usage scenarios
          • Increased VM warmup time in performance tests
          • Performance test results report: replaced simple average with sampling distribution

          v2 changes
          ----------

          • API changes for log4j-beta4 (trunk) from beta-3
          • Included lmax.disruptor-2.10.4 source to avoid external dependency
          • New feature: AsyncLogger now correctly passes configuration properties to log events
          • RingBuffer size is now configurable with System property "AsyncLogger.RingBufferSize"
          • Changed default for immediateFlush to true for FastFileAppender and
            RollingFastFileAppender (to be in line with standard *FileAppender)
          • Replaced System.out.println with StatusLogger.debug in AsyncLogger
          • Changed package name log4j.async to org.apache.logging.log4j.core.async
          • Changed package name log4j.appenders to org.apache.logging.log4j.core.async.appender
          • Formatted all source with spaces instead of tabs
          • Added Apache License notice file header to all source files
          • Implementations for JIRA items LOG4J2-151, LOG4J2-154 and LOG4J2-157
          • To run performance tests (AsyncLoggerPerfTest.bat and SyncLoggerPerfTest.bat),
            you need to supply
            log4j-api-2.0-beta4-SNAPSHOT.jar and
            log4j-core-2.0-beta4-SNAPSHOT.jar

          Implemented JIRA items:

          • LOG4J2-151 (a): changed visibility of method
            org.apache.logging.log4j.core.LoggerContext#newInstance from
            private to protected (line 330)

          (b) changed visibility of method
          org.apache.logging.log4j.core.Logger$PrivateConfig#logEvent(LogEvent)
          from protected to public (line 268)

          • LOG4J2-154: - ThreadContext performance improvement: copy the internal
            data structure for every modification, so we don't need to make
            a deep copy when returning an immutable Map or Stack.
          • same for DefaultThreadContextMap
          • added method getImmutableContext to ThreadContextMap:
            a fast implementation of this method is key to performance
          • LOG4J2-157: added method org.apache.logging.log4j.core.config.LoggerConfig#getProperties
            (line 275)
          Show
          Remko Popma added a comment - v3 changes ---------- Added performance tests for multi-threaded usage scenarios Increased VM warmup time in performance tests Performance test results report: replaced simple average with sampling distribution v2 changes ---------- API changes for log4j-beta4 (trunk) from beta-3 Included lmax.disruptor-2.10.4 source to avoid external dependency New feature: AsyncLogger now correctly passes configuration properties to log events RingBuffer size is now configurable with System property "AsyncLogger.RingBufferSize" Changed default for immediateFlush to true for FastFileAppender and RollingFastFileAppender (to be in line with standard *FileAppender) Replaced System.out.println with StatusLogger.debug in AsyncLogger Changed package name log4j.async to org.apache.logging.log4j.core.async Changed package name log4j.appenders to org.apache.logging.log4j.core.async.appender Formatted all source with spaces instead of tabs Added Apache License notice file header to all source files Implementations for JIRA items LOG4J2-151 , LOG4J2-154 and LOG4J2-157 To run performance tests (AsyncLoggerPerfTest.bat and SyncLoggerPerfTest.bat), you need to supply log4j-api-2.0-beta4-SNAPSHOT.jar and log4j-core-2.0-beta4-SNAPSHOT.jar Implemented JIRA items: LOG4J2-151 (a): changed visibility of method org.apache.logging.log4j.core.LoggerContext#newInstance from private to protected (line 330) (b) changed visibility of method org.apache.logging.log4j.core.Logger$PrivateConfig#logEvent(LogEvent) from protected to public (line 268) LOG4J2-154 : - ThreadContext performance improvement: copy the internal data structure for every modification, so we don't need to make a deep copy when returning an immutable Map or Stack. same for DefaultThreadContextMap added method getImmutableContext to ThreadContextMap: a fast implementation of this method is key to performance LOG4J2-157 : added method org.apache.logging.log4j.core.config.LoggerConfig#getProperties (line 275)
          Hide
          Ralph Goers added a comment -

          One thing I am considering is the possibility of making the LoggerConfigs asynchronous instead of or in addition to having the ability to have the Loggers be asynchronous. I can definitely envision the use case where debug logging would want to be asynchronous while audit logging would not. Having this at the LoggerConfig level would allow that. The only downsides to this approach that I can think of are:

          1. A slight loss in performance.
          2. The complexity of having to deal with an asynchronous logger trying to delegate to a synchronous parent logger via not setting additivity=false.

          Thoughts?

          Show
          Ralph Goers added a comment - One thing I am considering is the possibility of making the LoggerConfigs asynchronous instead of or in addition to having the ability to have the Loggers be asynchronous. I can definitely envision the use case where debug logging would want to be asynchronous while audit logging would not. Having this at the LoggerConfig level would allow that. The only downsides to this approach that I can think of are: 1. A slight loss in performance. 2. The complexity of having to deal with an asynchronous logger trying to delegate to a synchronous parent logger via not setting additivity=false. Thoughts?
          Hide
          Remko Popma added a comment - - edited

          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 (extends LoggerConfig):
          @Override
          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
          // TODO change RingBufferLogEvent.getMessage to return (message==null) ? new SimpleMessage("") : message;

          public void actualAsyncLog(RingBufferLogEvent event)

          { // this is executed in the I/O thread config.getConfigurationMonitor().checkConfiguration(); // logger may now have a different config Configuration updated = event.getLogger().getContext().getConfiguration(); String name = event.getLogger().getName(); event.mergePropertiesIntoContextMap( updated.getLoggerConfig(name).getProperties(), updated.getSubst()); event.getLogger().actualLog(event); }
          Show
          Remko Popma added a comment - - edited 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 (extends LoggerConfig): @Override 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 // TODO change RingBufferLogEvent.getMessage to return (message==null) ? new SimpleMessage("") : message; public void actualAsyncLog(RingBufferLogEvent event) { // this is executed in the I/O thread config.getConfigurationMonitor().checkConfiguration(); // logger may now have a different config Configuration updated = event.getLogger().getContext().getConfiguration(); String name = event.getLogger().getName(); event.mergePropertiesIntoContextMap( updated.getLoggerConfig(name).getProperties(), updated.getSubst()); event.getLogger().actualLog(event); }
          Hide
          Ralph Goers added a comment -

          The "slight loss" of performance I was speaking of is that the asynchronous LoggerConfig is invoked slightly later than where the asynchronous Logger would be so it would take slightly longer to return control to the application. However, I doubt it would be important.

          I believe parent delegation would work simply by scheduling the async loggers instead of calling them. We would still check them for additvity. In other words, the easy way to implement this would be to simply have the call to callAppenders be done synchronously or asynchronously and leave everything else in the calling thread.

          Show
          Ralph Goers added a comment - The "slight loss" of performance I was speaking of is that the asynchronous LoggerConfig is invoked slightly later than where the asynchronous Logger would be so it would take slightly longer to return control to the application. However, I doubt it would be important. I believe parent delegation would work simply by scheduling the async loggers instead of calling them. We would still check them for additvity. In other words, the easy way to implement this would be to simply have the call to callAppenders be done synchronously or asynchronously and leave everything else in the calling thread.
          Hide
          Remko Popma added a comment - - edited

          About the "slight loss" of performance: if it is just a couple of additional method calls, I doubt there will be any impact.
          I am more concerned about the current Logger.log implementation:
          configurationMonitor.checkConfiguration() call may access the file system (1 or 2 calls to file.lastModified(), potentially reloading the config file) so I would like to ensure that this happens in the I/O thread.

          About parent delegation, I'm trying to understand what you mean. I think there are 4 additivity=true delegation scenarios:
          1. sync child -> async parent
          2. async child -> sync parent
          3. sync child -> sync parent
          4. async child-> async parent

          In 1 and 3, the call to child.log(LogEvent) would be in the application thread.
          In 2 and 4, the call to child.log(LogEvent) would be in the I/O thread.

          What is it you are trying to achieve?
          If the child is the sync audit logger, and the parent is the async debug logger, you want the call to auditChild.callAppenders to be synchronously (in the application thread) and the call to debugParent.callAppenders to be asynchronously (in the I/O thread)?

          Show
          Remko Popma added a comment - - edited About the "slight loss" of performance: if it is just a couple of additional method calls, I doubt there will be any impact. I am more concerned about the current Logger.log implementation: configurationMonitor.checkConfiguration() call may access the file system (1 or 2 calls to file.lastModified(), potentially reloading the config file) so I would like to ensure that this happens in the I/O thread. About parent delegation, I'm trying to understand what you mean. I think there are 4 additivity=true delegation scenarios: 1. sync child -> async parent 2. async child -> sync parent 3. sync child -> sync parent 4. async child-> async parent In 1 and 3, the call to child.log(LogEvent) would be in the application thread. In 2 and 4, the call to child.log(LogEvent) would be in the I/O thread. What is it you are trying to achieve? If the child is the sync audit logger, and the parent is the async debug logger, you want the call to auditChild.callAppenders to be synchronously (in the application thread) and the call to debugParent.callAppenders to be asynchronously (in the I/O thread)?
          Hide
          Ralph Goers added a comment -

          I believe the call to checkConfiguration used to be in LoggerConfig but I had to move it to the Logger to avoid some problems, but I don't recall what they were now.

          By definition, if a synchronous logger is called from a child thread it is no longer synchronous and may not behave in the way the application expects. In a sense, delegation really isn't delegation. If LoggerConfig a.b.c is asynchronous it can be scheduled and then its parent can immediately be processed in the same thread that scheduled a.b.c. This has the desirable effect that if an exception is thrown and suppressExceptions is set to false then the application will receive the exception. This behavior is impossible to accomodate if the synchronous LoggerConfig is invoked from an asynchronous one.

          In other words - what you are expressing would result in a configuration that behaves like:

          <asynchLogger name="a.b.c" level="debug">
          <appender-ref ref="appender1"/>
          <logger name="a.b" level="debug">
          <appender-ref ref="appender2"/>
          </logger>
          </asynchLogger>

          even though what they actually configured was:

          <asynchLogger name="a.b.c" level="debug">
          <appender-ref ref="appender1"/>
          <asynchLogger>

          <logger name="a.b" level="debug">
          <appender-ref ref="appender2"/>
          </logger>

          Show
          Ralph Goers added a comment - I believe the call to checkConfiguration used to be in LoggerConfig but I had to move it to the Logger to avoid some problems, but I don't recall what they were now. By definition, if a synchronous logger is called from a child thread it is no longer synchronous and may not behave in the way the application expects. In a sense, delegation really isn't delegation. If LoggerConfig a.b.c is asynchronous it can be scheduled and then its parent can immediately be processed in the same thread that scheduled a.b.c. This has the desirable effect that if an exception is thrown and suppressExceptions is set to false then the application will receive the exception. This behavior is impossible to accomodate if the synchronous LoggerConfig is invoked from an asynchronous one. In other words - what you are expressing would result in a configuration that behaves like: <asynchLogger name="a.b.c" level="debug"> <appender-ref ref="appender1"/> <logger name="a.b" level="debug"> <appender-ref ref="appender2"/> </logger> </asynchLogger> even though what they actually configured was: <asynchLogger name="a.b.c" level="debug"> <appender-ref ref="appender1"/> <asynchLogger> <logger name="a.b" level="debug"> <appender-ref ref="appender2"/> </logger>
          Hide
          Remko Popma added a comment -

          So, if I understand correctly, you are talking about scenario 2:
          async child -> sync parent

          and you want the async child to do its logging in the I/O thread, and the sync parent to do its logging in the calling application thread?

          Show
          Remko Popma added a comment - So, if I understand correctly, you are talking about scenario 2: async child -> sync parent and you want the async child to do its logging in the I/O thread, and the sync parent to do its logging in the calling application thread?
          Hide
          Remko Popma added a comment -

          Ok, I think I get it.
          You were right, this additivity thing makes mixing synchronous and asynchronous loggers quite complex...

          My main concern is speed, so I'd like to keep the AsyncLogger and
          have the AsyncLoggerConfig in addition for the flexibility that it offers.

          Would you like me to take a stab at implementing AsyncLoggerConfig this weekend?

          Show
          Remko Popma added a comment - Ok, I think I get it. You were right, this additivity thing makes mixing synchronous and asynchronous loggers quite complex... My main concern is speed, so I'd like to keep the AsyncLogger and have the AsyncLoggerConfig in addition for the flexibility that it offers. Would you like me to take a stab at implementing AsyncLoggerConfig this weekend?
          Hide
          Ralph Goers added a comment -

          Sure. My first instinct is to create a new AsyncLoggerConfig plugin which extends LoggerConfig and overrides the callAppenders method. Although this doesn't address your concern with checking the configuration, I think it will be easy to implement, have almost no side effects and still provide good performance improvements. However, if you come up with a better way I'm open to it.

          Show
          Ralph Goers added a comment - Sure. My first instinct is to create a new AsyncLoggerConfig plugin which extends LoggerConfig and overrides the callAppenders method. Although this doesn't address your concern with checking the configuration, I think it will be easy to implement, have almost no side effects and still provide good performance improvements. However, if you come up with a better way I'm open to it.
          Hide
          Remko Popma added a comment -

          ok, I'll start there.

          Show
          Remko Popma added a comment - ok, I'll start there.
          Hide
          Remko Popma added a comment -

          Ralph, please find attached FastLog4j-v4-for-beta4.zip.

          While working on this issue I ran into the location issue again: Unconditionally taking stacktrace element snapshots makes AsyncLoggerConfig three times slower than the standard LoggerConfig when location is not necessary.

          Performance test results (on Windows laptop):
          root + %location pattern: ~40 microsec
          root without %location: ~5.4 microsec
          asyncRoot (default) : ~15 microsec <-- slower than sync logger without location: LOG4J2-153 needed
          asyncRoot + needsLocation=false: 0.6 microsec

          This would make AsyncLoggerConfig useless when users don't need location.

          So I went ahead and included a solution for LOG4J2-153: add a "needsLocation" attribute to the logger and asyncLogger config.
          The default would be "true", that is, include location information (so it is backwards compatible).

          What do you think?

          v4 changes
          ----------

          • (LOG4J2-163) Added AsyncLoggerConfig to enable mixing sync and async loggers
            Various changes for LOG4J2-163 and LOG4J2-153:
          • Added plugin attribute "needsLocation" to both LoggerConfig and AsyncLoggerConfig
          • Added method isLocationRequired() to LoggerConfig
          • Extracted code from Log4jLogEvent.getSource() into static method
            Log4jLogEvent.calcLocation so it can be re-used in AsyncLogger
          • AsyncLogger now includes location StackTraceElement unless
            config.loggerConfig.isLocationRequired() returns false
          • Modified core.Logger$PrivateConfig to make its config and loggerConfig fields
            visible for Logger subclasses
          • added methods isLocationRequired/setLocationRequired to interface LogEvent
            and impl classes Log4jLogEvent and RingBufferLogEvent
          • Additivity of location in logger hierarchy: in LoggerConfig.log,
            call LogEvent.setLocationRequired with config "needsLocation" attribute value
          • Log4jLogEvent.getSource checks isLocationRequired before initializing stackTraceElement
          • (LOG4J2-164) added methods isEndOfBatch/setEndOfBatch to LogEvent interface
            and impl classes Log4jLogEvent and RingBufferLogEvent.
            (If accepted I'll make follow-up changes to the FastXxxAppender classes.)
          • (Misc) Added ExceptionHandler support to AsyncLogger and AsyncLoggerConfig
          • (Misc) Bugfix in RingBufferLogEvent

          Affected classes:
          src/org/apache/logging/log4j/core/LogEvent
          src/org/apache/logging/log4j/core/Logger
          src/org/apache/logging/log4j/core/async/AsyncLogger
          src/org/apache/logging/log4j/core/async/RingBufferLogEvent
          src/org/apache/logging/log4j/core/config/LoggerConfig
          src/org/apache/logging/log4j/core/config/async/AsyncLoggerConfig
          src/org/apache/logging/log4j/core/impl/Log4jLogEvent
          perftest/*
          test/*

          Show
          Remko Popma added a comment - Ralph, please find attached FastLog4j-v4-for-beta4.zip. While working on this issue I ran into the location issue again: Unconditionally taking stacktrace element snapshots makes AsyncLoggerConfig three times slower than the standard LoggerConfig when location is not necessary. Performance test results (on Windows laptop): root + %location pattern: ~40 microsec root without %location: ~5.4 microsec asyncRoot (default) : ~15 microsec <-- slower than sync logger without location: LOG4J2-153 needed asyncRoot + needsLocation=false: 0.6 microsec This would make AsyncLoggerConfig useless when users don't need location. So I went ahead and included a solution for LOG4J2-153 : add a "needsLocation" attribute to the logger and asyncLogger config. The default would be "true", that is, include location information (so it is backwards compatible). What do you think? v4 changes ---------- ( LOG4J2-163 ) Added AsyncLoggerConfig to enable mixing sync and async loggers Various changes for LOG4J2-163 and LOG4J2-153 : Added plugin attribute "needsLocation" to both LoggerConfig and AsyncLoggerConfig Added method isLocationRequired() to LoggerConfig Extracted code from Log4jLogEvent.getSource() into static method Log4jLogEvent.calcLocation so it can be re-used in AsyncLogger AsyncLogger now includes location StackTraceElement unless config.loggerConfig.isLocationRequired() returns false Modified core.Logger$PrivateConfig to make its config and loggerConfig fields visible for Logger subclasses added methods isLocationRequired/setLocationRequired to interface LogEvent and impl classes Log4jLogEvent and RingBufferLogEvent Additivity of location in logger hierarchy: in LoggerConfig.log, call LogEvent.setLocationRequired with config "needsLocation" attribute value Log4jLogEvent.getSource checks isLocationRequired before initializing stackTraceElement ( LOG4J2-164 ) added methods isEndOfBatch/setEndOfBatch to LogEvent interface and impl classes Log4jLogEvent and RingBufferLogEvent. (If accepted I'll make follow-up changes to the FastXxxAppender classes.) (Misc) Added ExceptionHandler support to AsyncLogger and AsyncLoggerConfig (Misc) Bugfix in RingBufferLogEvent Affected classes: src/org/apache/logging/log4j/core/LogEvent src/org/apache/logging/log4j/core/Logger src/org/apache/logging/log4j/core/async/AsyncLogger src/org/apache/logging/log4j/core/async/RingBufferLogEvent src/org/apache/logging/log4j/core/config/LoggerConfig src/org/apache/logging/log4j/core/config/async/AsyncLoggerConfig src/org/apache/logging/log4j/core/impl/Log4jLogEvent perftest/* test/*
          Hide
          Remko Popma added a comment -

          Ralph, would you like me to start working on a Manual page for asynchronous loggers or do you need more time to decide whether this should be an integral part of Log4j?

          Show
          Remko Popma added a comment - Ralph, would you like me to start working on a Manual page for asynchronous loggers or do you need more time to decide whether this should be an integral part of Log4j?
          Hide
          Ralph Goers added a comment -

          Could you please rework the patch to make it be a separate Maven module - log4j-async. Ideally I would like it as a patch file where I could run the patch command to apply it to trunk, however I could take a zip of the new module and then just patches for the modifications to the existing stuff.

          Also, I build and run on a Mac and for some reason I could not run the binaries you put in one of your previous patches. I finally had to recompile them.

          I also noted that you are running your tests without specifying -server. You should always do that on Windows.

          Show
          Ralph Goers added a comment - Could you please rework the patch to make it be a separate Maven module - log4j-async. Ideally I would like it as a patch file where I could run the patch command to apply it to trunk, however I could take a zip of the new module and then just patches for the modifications to the existing stuff. Also, I build and run on a Mac and for some reason I could not run the binaries you put in one of your previous patches. I finally had to recompile them. I also noted that you are running your tests without specifying -server. You should always do that on Windows.
          Hide
          Remko Popma added a comment -

          Understood. I'm new to Maven but will give it a try. Sorry for the inconvenience with the binaries.
          When you say the patch command, you mean the Maven patch plugin? (I was sending you Eclipse-generated patches previously...)

          You are right about the -server. I was using 64-bit java so the JVM always assumes -server. I also made sure to warm-up for at least 10 secs for any performance test because the JVM behaves differently during the first 4 sec or so after startup.

          Show
          Remko Popma added a comment - Understood. I'm new to Maven but will give it a try. Sorry for the inconvenience with the binaries. When you say the patch command, you mean the Maven patch plugin? (I was sending you Eclipse-generated patches previously...) You are right about the -server. I was using 64-bit java so the JVM always assumes -server. I also made sure to warm-up for at least 10 secs for any performance test because the JVM behaves differently during the first 4 sec or so after startup.
          Hide
          Remko Popma added a comment - - edited

          Maven question:
          How do you get Maven to compile AbstractStringLayout.ClassEncoder with JDK6 (in package org.apache.logging.log4j.core.layout), and all the other classes with JDK5? I have some JDK6-only functionality and would like to do something similar for the log4j-async module...

          Show
          Remko Popma added a comment - - edited Maven question: How do you get Maven to compile AbstractStringLayout.ClassEncoder with JDK6 (in package org.apache.logging.log4j.core.layout), and all the other classes with JDK5? I have some JDK6-only functionality and would like to do something similar for the log4j-async module...
          Hide
          Ralph Goers added a comment -

          You found a bug. I don't actually use Java 5 to compile - I use Java 6 or 7 so that code compiles fine. However, since the code is compiled for a target of Java 5 and the constructor checks to see if the method exists it should run fine in Java 5. I suspect that I should change the "compile source" setting in the parent pom to 1.6 instead of 1.5.

          Show
          Ralph Goers added a comment - You found a bug. I don't actually use Java 5 to compile - I use Java 6 or 7 so that code compiles fine. However, since the code is compiled for a target of Java 5 and the constructor checks to see if the method exists it should run fine in Java 5. I suspect that I should change the "compile source" setting in the parent pom to 1.6 instead of 1.5.
          Hide
          Remko Popma added a comment -

          I found some other classes that don't compile with JDK5:
          org.apache.logging.log4j.core.helpers.UUIDUtil
          org.apache.logging.log4j.core.layout.HtmlLayout
          org.apache.logging.log4j.core.layout.XmlLayout
          org.apache.logging.log4j.message.ExtendedThreadInformation
          org.apache.logging.log4j.message.LocalizedMessage
          org.apache.logging.log4j.message.ThreadDumpMessage

          What is the rationale for targeting JDK5?
          I would think that people/companies conservative enough to not upgrade Java are very unlikely to switch their logger from Log4j to Log4j2 as well...
          (Note that as of last month, JDK6 is now officially End of Public Updates: http://www.oracle.com/technetwork/java/eol-135779.html )

          Show
          Remko Popma added a comment - I found some other classes that don't compile with JDK5: org.apache.logging.log4j.core.helpers.UUIDUtil org.apache.logging.log4j.core.layout.HtmlLayout org.apache.logging.log4j.core.layout.XmlLayout org.apache.logging.log4j.message.ExtendedThreadInformation org.apache.logging.log4j.message.LocalizedMessage org.apache.logging.log4j.message.ThreadDumpMessage What is the rationale for targeting JDK5? I would think that people/companies conservative enough to not upgrade Java are very unlikely to switch their logger from Log4j to Log4j2 as well... (Note that as of last month, JDK6 is now officially End of Public Updates: http://www.oracle.com/technetwork/java/eol-135779.html )
          Hide
          Ralph Goers added a comment -

          Thanks. That makes it even more compelling to require Java 6 for compilation. The rationale for targeting JDK5 is simply that we haven't run into anything that prevents us from doing that. However, I think that I am going to change that since I never actually test on Java 5 and unless I, or someone else, is willing to do that in every release then we shouldn't claim to support it.

          Show
          Ralph Goers added a comment - Thanks. That makes it even more compelling to require Java 6 for compilation. The rationale for targeting JDK5 is simply that we haven't run into anything that prevents us from doing that. However, I think that I am going to change that since I never actually test on Java 5 and unless I, or someone else, is willing to do that in every release then we shouldn't claim to support it.
          Hide
          Gary Gregory added a comment -

          I am all for Java 6 as the requirement.

          Show
          Gary Gregory added a comment - I am all for Java 6 as the requirement.
          Hide
          Remko Popma added a comment -

          Sorry for the long wait. Please find attached file LOG4J2-163-log4j-async.patch.

          This file contains the async loggers and FastFileAppenders in a new module log4j-async, and also contains patches for the following JIRA tickets that the log4j-async module depends on:
          LOG4J2-151
          LOG4J2-153
          LOG4J2-157
          LOG4J2-164

          I also updated pom.xml to add the module and change the compilation version to Java 6.

          Show
          Remko Popma added a comment - Sorry for the long wait. Please find attached file LOG4J2-163 -log4j-async.patch. This file contains the async loggers and FastFileAppenders in a new module log4j-async, and also contains patches for the following JIRA tickets that the log4j-async module depends on: LOG4J2-151 LOG4J2-153 LOG4J2-157 LOG4J2-164 I also updated pom.xml to add the module and change the compilation version to Java 6.
          Hide
          Remko Popma added a comment -

          Please find attached file LOG4J2-163-log4j-async-20130320.patch.

          Changes:

          • Updated for changes in trunk
          • Upgraded to latest version of LMAX Disruptor (3.0.0-beta3) for better performance in multi-threaded scenarios
          • Added manual page (src/site/xdoc/manual/async.xml)
          • Added performance and JUnit tests
          • Various small improvements

          As before the patch file contains the new module log4j-async, and also contains patches for the following JIRA tickets that the log4j-async module depends on:
          LOG4J2-151
          LOG4J2-153
          LOG4J2-157
          LOG4J2-164

          I also updated pom.xml to add the module and change the compilation version to Java 6.

          Show
          Remko Popma added a comment - Please find attached file LOG4J2-163 -log4j-async-20130320.patch. Changes: Updated for changes in trunk Upgraded to latest version of LMAX Disruptor (3.0.0-beta3) for better performance in multi-threaded scenarios Added manual page (src/site/xdoc/manual/async.xml) Added performance and JUnit tests Various small improvements As before the patch file contains the new module log4j-async, and also contains patches for the following JIRA tickets that the log4j-async module depends on: LOG4J2-151 LOG4J2-153 LOG4J2-157 LOG4J2-164 I also updated pom.xml to add the module and change the compilation version to Java 6.
          Hide
          Remko Popma added a comment -

          I compared performance of log4j2-async with log4j-1.x and logback:
          Log4j2-async is significantly faster, especially in multi-threaded scenarios.

          1 thread: 20% faster, 2 threads: 45% faster, 4 threads: 2.5x faster, 8 threads: 3.2x faster

          Throughput in logged messages per second:
          ____________________________ 1 thread 2 threads 4 threads 8 threads
          Log4j2: All async (SysClock) 2,652,412 909,119 776,993 516,365
          Log4j2: Async Appender _____ 1,713,429 603,019 331,506 149,408
          Log4j1: Async Appender _____ 2,239,664 494,470 221,402 109,314
          Logback: Async Appender ____ 2,206,907 624,082 307,500 160,096

          Log4j2: Sync 273,536 136,523 67,609 34,404
          Log4j1: Sync 326,894 105,591 57,036 30,511
          Logback: Sync 178,063 65,000 34,372 16,903

          For synchronous logging, I experimented with replacing DatePatternConverter with a dummy impl, but this only increased throughput to 287,113 ops/sec.

          Show
          Remko Popma added a comment - I compared performance of log4j2-async with log4j-1.x and logback: Log4j2-async is significantly faster, especially in multi-threaded scenarios. 1 thread: 20% faster, 2 threads: 45% faster, 4 threads: 2.5x faster, 8 threads: 3.2x faster Throughput in logged messages per second: ____________________________ 1 thread 2 threads 4 threads 8 threads Log4j2: All async (SysClock) 2,652,412 909,119 776,993 516,365 Log4j2: Async Appender _____ 1,713,429 603,019 331,506 149,408 Log4j1: Async Appender _____ 2,239,664 494,470 221,402 109,314 Logback: Async Appender ____ 2,206,907 624,082 307,500 160,096 Log4j2: Sync 273,536 136,523 67,609 34,404 Log4j1: Sync 326,894 105,591 57,036 30,511 Logback: Sync 178,063 65,000 34,372 16,903 For synchronous logging, I experimented with replacing DatePatternConverter with a dummy impl, but this only increased throughput to 287,113 ops/sec.
          Hide
          Remko Popma added a comment -

          Just for fun I attached a graph comparing the throughput performance of async loggers to async appenders (incl. log4j-1.x and logback).

          Ralph, I hope to submit an updated patch that includes the LOG4J2-153 changes this weekend.

          Show
          Remko Popma added a comment - Just for fun I attached a graph comparing the throughput performance of async loggers to async appenders (incl. log4j-1.x and logback). Ralph, I hope to submit an updated patch that includes the LOG4J2-153 changes this weekend.
          Hide
          Remko Popma added a comment - - edited

          Please find attached files LOG4J2-163-log4j-async-20130331.patch
          and LOG4J2-163-log4j-async-20130331-images.zip

          Changes:

          • LOG4J2-153 includeLocation attribute on LoggerConfig and AsyncAppender with proper defaulting
          • Updated async manual page

          The images in the zip file are referenced in the manual page and should be placed in the
          src/site/resources/images/ directory.

          Show
          Remko Popma added a comment - - edited Please find attached files LOG4J2-163 -log4j-async-20130331.patch and LOG4J2-163 -log4j-async-20130331-images.zip Changes: LOG4J2-153 includeLocation attribute on LoggerConfig and AsyncAppender with proper defaulting Updated async manual page The images in the zip file are referenced in the manual page and should be placed in the src/site/resources/images/ directory.
          Hide
          Ralph Goers added a comment -

          I started to look at the code and I have a couple of issues:
          1. @author tags are discouraged by the ASF board of directors and Log4j 2 doesn't use them. The idea here is that the community owns the code. Individual contributions are recognized through the changes.xml and subversion commits.
          2. I am seeing com.lmax.disruptor classes in the source code. This is very bad practice as it means a log4j jar will now be exposing classes from a third party. The pom.xml should reference the disruptor jar as a dependency. I'd fix this but I don't know what version you based this on.

          Show
          Ralph Goers added a comment - I started to look at the code and I have a couple of issues: 1. @author tags are discouraged by the ASF board of directors and Log4j 2 doesn't use them. The idea here is that the community owns the code. Individual contributions are recognized through the changes.xml and subversion commits. 2. I am seeing com.lmax.disruptor classes in the source code. This is very bad practice as it means a log4j jar will now be exposing classes from a third party. The pom.xml should reference the disruptor jar as a dependency. I'd fix this but I don't know what version you based this on.
          Hide
          Gary Gregory added a comment -

          The pom.xml is the best place is acknowledge contributors IMO.

          Show
          Gary Gregory added a comment - The pom.xml is the best place is acknowledge contributors IMO.
          Hide
          Remko Popma added a comment - - edited

          Ralph, Gregory, thanks for your feedback!
          Please find attached file LOG4J2-163-log4j-async-20130331a.patch

          This fixes the issues you mentioned:

          • removed @author tags from source code
          • removed com.lmax classes, declared dependency in pom, fixed imports and updated documentation

          The disruptor version I used is 3.0.0.beta3.

          (the images referenced in the manual have not changed, so I did not upload them again. Please unzip them into the src/site/resources/images/ directory)

          Show
          Remko Popma added a comment - - edited Ralph, Gregory, thanks for your feedback! Please find attached file LOG4J2-163 -log4j-async-20130331a.patch This fixes the issues you mentioned: removed @author tags from source code removed com.lmax classes, declared dependency in pom, fixed imports and updated documentation The disruptor version I used is 3.0.0.beta3. (the images referenced in the manual have not changed, so I did not upload them again. Please unzip them into the src/site/resources/images/ directory)
          Hide
          Ralph Goers added a comment -

          Patch applied in revision 1463078. Please verify and close.

          Show
          Ralph Goers added a comment - Patch applied in revision 1463078. Please verify and close.
          Hide
          Remko Popma added a comment -

          I found one issue: the image files (used in the async manual page) have not been committed yet.
          Could you unzip the attached file LOG4J2-163-log4j-async-20130331-images.zip and copy the 3 image files to the src/site/resources/images/ directory?

          Show
          Remko Popma added a comment - I found one issue: the image files (used in the async manual page) have not been committed yet. Could you unzip the attached file LOG4J2-163 -log4j-async-20130331-images.zip and copy the 3 image files to the src/site/resources/images/ directory?
          Hide
          Ralph Goers added a comment -

          They were committed in a subsequent checkin. Please re-checkout to confirm that they are there.

          Show
          Ralph Goers added a comment - They were committed in a subsequent checkin. Please re-checkout to confirm that they are there.
          Hide
          Remko Popma added a comment -

          Yes, they are there now. This is great! Thank you for checking this huge patch!

          Show
          Remko Popma added a comment - Yes, they are there now. This is great! Thank you for checking this huge patch!
          Hide
          Remko Popma added a comment -

          Please find attached files documentation-update-images-20130402.patch and documentation-update-20130402.patch.

          They contain updates for the async manual page, the overall performance page and the team page (I added myself as a contributor, I hope that is ok.)

          Please unzip the images into the src/site/resources/images/ directory.

          Show
          Remko Popma added a comment - Please find attached files documentation-update-images-20130402.patch and documentation-update-20130402.patch. They contain updates for the async manual page, the overall performance page and the team page (I added myself as a contributor, I hope that is ok.) Please unzip the images into the src/site/resources/images/ directory.
          Hide
          Remko Popma added a comment -

          Removed attached files documentation-update-images-20130402.patch and documentation-update-20130402.patch.
          I proposed a patch for LOG4J2-193 which has the same documentation changes. Sorry for the confusion.

          Show
          Remko Popma added a comment - Removed attached files documentation-update-images-20130402.patch and documentation-update-20130402.patch. I proposed a patch for LOG4J2-193 which has the same documentation changes. Sorry for the confusion.

            People

            • Assignee:
              Ralph Goers
              Reporter:
              Remko Popma
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development