Log4j JMS Appender Performance Results

Posted by on July 10, 2012
Filed Under Performance Engineering | Comments Off

We recently came across a throughput issue with the Log4j JMS appender.  We were working with a client who was seeing throughput throttled as they went to high transaction rates on a Java web application.  Analysis of the thread dumps showed that the threads were synchronized on the Log4j Logger object.  We came across Ming Yuan’s blog post about a throughput issue when using a Log4j JMS appender.  His post helped us resolve the issue with the client and got us interested in doing some testing on the throughput ourselves.  Below are the results of our testing.

Methodology

Our testing approach was to create a web application that spawned a number of threads and wrote to a JMS queue using one of two methods, Log4j JMS appender or straight Java APIs.  We ran the application using a varying number of threads and varying delays between writes to the JMS queue.  The test environment consisted of

The Application

The application consists of a servlet to configure the test parameters and start the test, a message generator, a message receiver, some status objects, and a test status servlet.  Each test execution requires that several parameters be configured from the application’s main page.  Here is a screen shot.

For each test, we configured the number of message generation threads to spawn, the number of messages that each thread will send before it shuts down, the amount of delay between each message publication, and the method to use for sending the message (either Log4J or native Java).  We also spawned a subscriber thread.  The subscriber thread makes the test more realistic and prevents the Topic from exceeding its quota size.  We give an amount of time to run the subscriber and a delay between each message receive to simulate processing time.  We could have used a more advanced approach to do the receiveing, but didn’t want to put in the effort.

The JMS implementation we used was a durable topic running in the same instance as the application, i.e. no remote communication.  Remote queues could easily be tested by changing the queue configuration.

The main classes are:

RunTest – Servlet that saves the test configuration and spawns the appropriate number of message generation threads and the subscriber thread.

MessageGenerator – extends the thread class.  This class instantiates the appropriate type of JMS appender being used for this test.  It then executes a loop for the configured number of iterations publishing a message to the JMS queue. There is a configured delay between publishing each message.  The message is a String, however it is put on the queue as an ObjectMessage.  This is because the Log4j appender can only put ObjectMessage types on the queue and we wanted to be consistent to reduce the number of variables.  The TextMessage type should serialize faster, but is not supported by the Log4j JMS appender.

Log4jJMSAppender – this is a very simple class because all of the JMS connection information is in the Log4j configuration file.  This is also where the performance issue with the Log4j appender is seen.  Each thread refers to the single instance of the Log4j JMS appender, and access to write to that appender is synchronized.  The message that is put on the queue is an ObjectMessage and is of type org.apache.log4j.spi.LoggingEvent.

NativeJMSAppender – this class looks more complicated than the Log4jJMSAppender, but it really just contains the same items that are in the Log4j configuration file.  The big difference in performance comes from the fact that each thread is creating its own session with the JMS service so the messages are published in parallel rather than synchronized through a single object.

MessageReceiver – this extends the thread class.  It subscribes to the test topic and pulls messages off of the topic.  It sleeps between each message for a configurable delay to simulate message processing time.  It runs for the configured duration of time.

TestStatus – this is a servlet that displays the status of the currently running test.  When the test is complete, it displays a button to run another test. 

Here is the source code for the application.  It is a zipped Eclipse directory: jms-test

The Results

The purpose of this testing effort was to determine the maximum throughput of each coding approach.  We ran numerous combinations of the number of publish threads, number of messages to publish, and the delay between each publish operation.   The basic results were always the same.  Native Java code was much faster than a Log4j appender, and there was a hard ceiling for the Log4j appender. 

The charts below show the tests that achieved the maximum throughput.  The Log4j JMS Appender had a very hard throughput limit of 300 messages per second with our configuration.  However, the native JMS code was able to achieve 33,238 message per second. 

 

The server we were using had significant amounts of processing power and memory.  Different bottlenecks may be encountered when running on a less powerful server.  The discussion thread about using an Asynch appender may be more of a factor on a server with less processing capacity.  We tested with both an Asynch Appender and a straight JMS Appender and the results were exactly the same.  This is because the throughput issue with Log4j was the synchronized access to the Logger object.  The creation of the ObjectMessage talked about in the thread discussion was not an issue on our server. 

Summary

The Log4j JMS Appender has an upper throughput limit in a multi-threaded environment because of synchronization on the Logger object.  If high throughput is needed, using straight Java code that creates a JMS session for each thread and writes in parallel is much faster, and not much more effort.



Comments

Comments are closed.