Asynchronous logging with log4j

by ricardoz on Nov.25, 2009, under Articles, Performance, Security

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.

:apache, java, java logging, log4j, logging, memory, Performance

8 Comments for this entry

Neeraj Jaiswal
September 7th, 2010 on 8:04 am
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
September 13th, 2010 on 9:46 pm
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.
ricardoz
September 13th, 2010 on 10:23 pm
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
October 11th, 2010 on 2:48 am
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.
ricardoz
October 12th, 2010 on 5:53 am
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
February 1st, 2011 on 5:06 am
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
November 14th, 2011 on 2:48 pm
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?
ricardoz
November 25th, 2011 on 11:42 am
@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.