posted 25-Nov-2009 | 21 comments | , , , , , ,

In case you are not doing it already, using asynchronous logging is generally a good idea. You don’t want your application to slow down if the server IO is a little behind flushing all that logging to the filesystem. By making it asynchronous your application can continue running without having to wait for the log lines to be written to their final destination.

My personal choice for Java logging is log4j, there are a lot of different frameworks (including Suns own logging API), but log4j works great and is extremely flexible.

Log4j provides a built-in appender that provides asynchronous event logging, this appender wraps around the appender you actually want to use (file, console, event log, etc.) and provides the required de-coupling.

To use it you need to configure log4j programatically or using XML, you cannot configure the asynchronous appender using a properties file. A very simple XML configuration file to use asynchronous logging writing the events to the console would be:

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd" >
<log4j:configuration>
	<appender name="stdout" class="org.apache.log4j.ConsoleAppender">
		<layout class="org.apache.log4j.PatternLayout">
			<param name="ConversionPattern" value="%d{yyyy/MM/dd HH:mm:ss,SSS} [%t] %-5p %c %x - %m%n"/>
		</layout>
	</appender>
        <appender name="ASYNC" class="org.apache.log4j.AsyncAppender">
            <param name="BufferSize" value="500"/>
            <appender-ref ref="stdout"/>
        </appender>
	<root>
		<priority value="error"></priority>
		<appender-ref ref="ASYNC"/>
	</root>
</log4j:configuration>

The root appender references the AsyncAppender, and the AsyncAppender references the ConsoleAppender in turn. If you want to define your own logger you just have to point it to the ASYNC appender:

<logger name="com.spartanjava" additivity="false">
    <level value="info" />
    <appender-ref ref="ASYNC" />
</logger>

A few tips on using AsyncAppender and log4j in general:

  • If you see duplicated entries on your log, make sure your logger has the additivity attribute set to false.
  • The BufferSize parameter of the AsyncAppender defines the number of entries that will be stored in memory to let the actual appender catch up flushing them to their final destination. If this buffer fills up, the logging will switch to a synchronous mode until buffer space becomes available, potentially becoming a performance issue. Make sure this buffer is big enough, taking into account the IO speed and number of log entries generated by your application.
  • You can add the Blocking parameter to the AsyncAppender definition in your config file, if you set it to false (the default value is true) when the buffer fills up, the appender will discard log events until new buffer space becomes available. This can be unacceptable in applications where logging information is critical, but on the other hand can be very desirable where performance is a critical factor.
  • http://www.technimi.com Neeraj Jaiswal

    Hey,

    I really like your article. Infact I was also working on improving the use of log4j.

    Check out this article of mine on version based login. Its just a basic code.

    http://www.technimi.com/index.php?do=/blog/version-based-logging-using-log4j/

  • Matrixstar

    Thank you for your nice article.

    Got a question about the below statement.

    “The BufferSize parameter of the AsyncAppender defines the number of entries that will be stored in memory to let the actual appender catch up flushing them to their final destination.”

    I tried AsyncAppender, but what I noticed is, the log message is sent to the destination appender (for example FileAppender) from AsyncAppender as soon the message is sent to AsyncAppender. Doesn’t AsyncAppender dispatcher thread wait until the buffer fills up? Your advise will be much appreciated.

  • http://www.spartanjava.com ricardoz

    No, it will try to flush it as soon as possible. The buffer is used in case the number of incoming events overcome the IO capability of the output file.

  • Ramesh

    Thanks for sharing the great article, can you clarify my questions

    1) when we use this async mode, whether the sequence of the log messages maintained? for me it is not. If the sequence is not maintained it does not make any sense rite?

    2) When the buffer fills us it will use sync mode, but is this part of user thread or separate thread by log4j? because the main point here is not to slowdown the user’s thread.

  • http://www.spartanjava.com ricardoz

    Ramesh, hi.

    1. It should be maintained, at least within the same thread in your application. Are you logging from a single thread environment?

    2. No, that’s exactly the purpose of the buffer, if it fills up it will cause en IO wait on your application until the logger can catch up. If you find this happening a lot, you should increase the buffer.

  • Vishak

    AsyncAppender uses FIFO (First in First Out) logic. It uses BoundedFIFO utility for this. Pls refer this documentation for more http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/helpers/BoundedFIFO.html

    So the sequence inwhich logging happens will be correct

  • Praveen

    Thanks for this simple explanation. I implemented this and worked fine, except that the filename/line number in the invoking method is not being displayed. Is there any other configuration involved?

  • http://www.spartanjava.com ricardoz

    @Praveen

    The info logged and the format of the log file itself are part of the log4j configuration. You can read about it on log4j official website (http://logging.apache.org/log4j/1.2/).

    Additionally you might want to check that your code is being compiled with the debbuging flag on, otherwise line numbers won’t be printed on stack traces.

  • Nickle

    It’s really cool article. I learned a lot from this. thank you very much.

  • http://devday.tistory.com izeye

    Thank you for this nice article.

    It helped me a lot :-)

  • Kalidoss

    Thank you for this article. Very much useful.

  • EDH

    What if the AsyncAppender’s buffers fills up ? Are the messages lost then ?

  • http://ricardozuasti.com/ Ricardo Zuasti

    @8a1a8fb87f92a35accbb7c4a183e7156:disqus No, it just puts the thread on hold until the buffer has enough free space (ie. it becomes synchronized for a while)

  • Rkdeveloper

    i like this concept

  • Rkdeveloper

     this is my reply

  • DRG

    I like this concept of async logging.. We had implemented this through JMS, I think this may be a better option given the resource availability

  • san

     Can anyone please help me to use this in a groovy project? I have been trying many ways, none seems to work.
    Thanks in advance

  • Pingback: Log4j를 좀더 빠르게 써보자!! « Beyondj2ee's Blog

  • Pingback: JavaPins

  • Smrutiranjan

    A very helpful piece of information. I would like to thank the Author. Keep up the good work.

  • nattyhacker