Ming has posted 2 posts at DZone. View Full User Profile

Think Again Before Adopting Log4j JMSAppenders

12.08.2010
| 12092 views |
  • submit to reddit

Log4j is a powerful and popular logging framework. In addition to providing good performance at run time, the framework also offers the flexibility to create your own logging components by implementing Log4j interfaces.

Appenders, in the terminology of log4j, are responsible for handling the output and transport of logging data. Customized Log4j appenders are often developed to meet the specific requirements of an application or an organization. More specifically, JMSAppenders are created to send logging messages to JMS queue. In fact, it is really easy to use such JMSAppenders in your application – just several lines of configuration definitions in your log4j.xml is sufficient enough to see your messages being sent to the pre-defined JMS destinations. Due to such simplicity, JMSAppenders are over used in many non-relevant circumstances, so be judicious in evaluating your need to have a JMSappender.

JMSAppenders are normally implemented in two ways.
1) The implmentation in the log4j Companion package, where JMSConnection, JMSSession and JMSSender objects are re-used through the whole life time of a JMSAppender.
2) A sample JMSAppender from IBM. It opens, and then closes, all JMS objects with the append method. Obviously, this type of implementations has some performance impact during runtime.

During testing, i found the first implementation performed 600 times faster than the second one. I don't recommand the second implementation. However, the first implementation may cause unexpected issues during the following situations. So think again before using any JMSAppenders.

When JMSAppender is associated to a “global” logger definition
You may create a root logger for your whole application, or you may invoke a singleton-based logging help class within your application.
When you associate your JMSAppender with a logger definition in your log4j.xml, Log4j instantiates only one JMSAppender object for the logger. In case, the logger can be utilized anywhere in your application, it is true that your whole application depends on a single JMSConnection to transport all messages.

When on heavy Loads.
“Heavy load” includes two situations: the volume of log messages is high, and/or, the size of each message is big. Log4j is designed as a thread-safe framework. It does a good job to dispatch images. However, under heavy load, things starts to change. In a test case which creates 10 threads and each of threads can invoke a JMSAppender 600 times. The testing results really surprised us.

Result 1 – We ran the test case; but commented out the line invoking the JMSAppender.

[LogThread[8]: Total time passed since start of application: 6031]
[LogThread[0]: Total time passed since start of application: 6094]
[LogThread[1]: Total time passed since start of application: 6156]
[LogThread[5]: Total time passed since start of application: 6188]
[LogThread[4]: Total time passed since start of application: 6266]
[LogThread[3]: Total time passed since start of application: 6313]
[LogThread[6]: Total time passed since start of application: 6391]
[LogThread[9]: Total time passed since start of application: 6406]
[LogThread[7]: Total time passed since start of application: 6469]
[LogThread[2]: Total time passed since start of application: 6485]


Result 2 – We built a timer within threads. Every 100 milliseconds, our code invokes the JMSAppender.

[LogThread[6]: Total time passed since start of application: 71430]
[LogThread[0]: Total time passed since start of application: 71477]
[LogThread[7]: Total time passed since start of application: 71477]
[LogThread[3]: Total time passed since start of application: 71492]
[LogThread[2]: Total time passed since start of application: 71571]
[LogThread[1]: Total time passed since start of application: 71586]
[LogThread[5]: Total time passed since start of application: 71649]
[LogThread[9]: Total time passed since start of application: 71664]
[LogThread[4]: Total time passed since start of application: 71805]
[LogThread[8]: Total time passed since start of application: 71820]


Result 3 – our testing code simply invokes the JMSAppender 600 times without any intervals. This case can test log4j’s behavior under heavy load.

[LogThread[1]: Total time passed since start of application: 761142]
[LogThread[9]: Total time passed since start of application: 800422]
[LogThread[3]: Total time passed since start of application: 802078]
[LogThread[5]: Total time passed since start of application: 804562]
[LogThread[7]: Total time passed since start of application: 812843]
[LogThread[6]: Total time passed since start of application: 815249]
[LogThread[8]: Total time passed since start of application: 817374]
[LogThread[2]: Total time passed since start of application: 817484]
[LogThread[4]: Total time passed since start of application: 817515]
[LogThread[0]: Total time passed since start of application: 817515]


From three test cases above, we can see the Log4j JMSAppender took much longer time during heavy load.

When true asynchronization is required
By default, Log4j appenders behave synchronously unless explicitly using its AsynAppender. In a JMSAppender, the time it takes to format and transport your messages is part of the same process in your application. Too many logging statements in your code can eventually slow down your application’s performance.

When content is critical to business processes
Log4j JMSAppenders are managed by the Log4j framework. The design principle is simply for logging purposes. This type of utility classes should not be used to send messages/events critical to your core business functions. It also should not be used when fail-over is required. The reason is simple. For applications with well defined logging strategy, the volume of logging messages should not be significantly changed during its peak time and normal time. This is a foundational assumption in logging frameworks. Using JMSAppender for business events breaks this assumption.

 

So what can we do when leveraging a JMSAppender?

  • Keep in mind logging utility classes should be used only for logging purposes.
  • Avoid binding JMSAppenders to any global loggers. Replace a global logger with multiple loggers for different packages, and associate JMSAppenders to each of these loggers with smaller scopes.
  • Use the service activator pattern when asynchronized behavior is required or sending business critical events. In some circumstances, you can use the pattern twice: use it once to de-couple message transprotation time; and use it again to decouple the time of message processing.
Published at DZone with permission of its author, Ming Yuan.

(Note: Opinions expressed in this article and its replies are the opinions of their respective authors and not those of DZone, Inc.)

Tags:

Comments

Martijn Verburg replied on Wed, 2010/12/08 - 9:40am

Interesting read - thanks for sharing!

Comment viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.