Integrating Log4j With Perf4j For Performance Logging

Perf4J is an open source framework used for monitoring and analyzing performance statistics of Java applications. Perf4j provides custom log4j appenders that can be used to integrate with log4j for capturing performance statistics along with general logging information.


Adding Per4j Appender and Logger to Log4j Config File

Shown below is a log4j configuration file with per4j appender and logger for gathering performance information.

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration>
    
    <appender name="console" class="org.apache.log4j.ConsoleAppender">
    	<param name="threshold" value="debug" />
        <layout class="org.apache.log4j.PatternLayout">
	    <param name="conversionPattern" value="%m%n"/>
	</layout>
    </appender>
    
    <!-- Perf4j Appender -->
<appender name="perf_appender" class="org.perf4j.log4j.AsyncCoalescingStatisticsAppender"> <param name="TimeSlice" value="5000"/> <appender-ref ref="console"/> </appender> <!-- Perf4j Logger --> <logger name="org.perf4j.TimingLogger" additivity="false"> <level value="DEBUG"/> <appender-ref ref="perf_appender"/> </logger> <logger name="examples" additivity="false"> <level value="debug"/> <appender-ref ref="console"/> </logger> <root> <level value="debug" /> <appender-ref ref="console"/> </root> </log4j:configuration>

We had defined a perf4j appender 'AsyncCoalescingStatisticsAppender' and named it as perf_appender. This appender takes a 'TimeSlice' parameter which indicates the time span (in milliseconds) after which the performance statistics should be published. It also requires a reference of a log4j appender to publish the information to the desire destination. We had provided a reference of the console appender in this example.

We have also defined a perf4j logger which will be used to gather the performance information form the java classes in our application. The perf4j appender reference is passed to this logger.

Dependency:

Per4j requires perf4j.jar; we should download and include it in the application classpath.


Java Class

We would use the simple java class shown below to demonstrate the performance logging.

package examples;

import org.apache.log4j.Logger;
import org.perf4j.StopWatch;
import org.perf4j.log4j.Log4JStopWatch;

public class TestLogging {
	
    public static Logger logger = Logger.getLogger(TestLogging.class);
	
    public static void main(String args[]){
		
	try{
  	    for(int i=0;i<10;i++){
		TestLogging log = new TestLogging();
		log.method1();
		log.method2();
		log.method3();
	    }
	}
	catch(InterruptedException ie){
	    ie.printStackTrace();
	}
    }
	
    public void method1() throws InterruptedException{
	StopWatch sw = new Log4JStopWatch("m1");
	if(logger.isDebugEnabled()){
	    logger.debug("In method1");
	}
	Thread.sleep((long)(1000L * Math.random()));
	sw.stop();
    }
	
    public void method2() throws InterruptedException{
	StopWatch sw = new Log4JStopWatch("m2");
	if(logger.isDebugEnabled()){
  	    logger.debug("In method2");
	}
	Thread.sleep((long)(1000L * Math.random()));
	sw.stop();
    }
	
    public void method3() throws InterruptedException{
	StopWatch sw = new Log4JStopWatch("m3");
	if(logger.isDebugEnabled()){
	    logger.debug("In method3");
	}
	Thread.sleep((long)(1000L * Math.random()));
	sw.stop();
    }
}

We had created three simple methods and used the Thread.sleep() method to ensure that the thread sleeps for a random period of time; so that each method take random time span to complete. In the main method we call these three methods one after the other for 10 times.

Perf4j provides a convenient way to capture the timing information through a stopwatch. We can created an instance of Log4JStopWatch class and give it a name (called as tag), which can be used to identify the method in the logs. On completion of each method we called the stop() method to stop the stopwatch.


Performance Statistics

Below is the performance statistics that gets printed on executing the java class:

Performance Statistics   2015-07-07 11:58:10 - 2015-07-07 11:58:15
Tag                                                  Avg(ms)         Min         Max     Std Dev       Count
m1                                                     348.0         201         591       155.1           4
m2                                                     605.0         267         951       279.3           3
m3                                                     517.0         313         857       242.0           3

Performance Statistics   2015-07-07 11:58:15 - 2015-07-07 11:58:20
Tag                                                  Avg(ms)         Min         Max     Std Dev       Count
m1                                                     530.5         302         723       151.5           4
m2                                                     485.8         220         893       255.6           4
m3                                                     241.0          62         454       140.4           4

Performance Statistics   2015-07-07 11:58:20 - 2015-07-07 11:58:25
Tag                                                  Avg(ms)         Min         Max     Std Dev       Count
m1                                                     476.0          31         921       445.0           2
m2                                                     693.0         373         868       226.6           3
m3                                                     633.0         513         774       107.6           3

Since we had mentioned '5000' as the timeslice in the config file, the performance statistics gets printed after evert 5 seconds.


Keeping the Code Clean

We can see that the stopwatch is littering around in the code. To keep our code clean we can remove the stopwatch from the method body. As an alternative we can take advantage of the @Profiled annotation, which uses AOP to record timing information. The sample code is shown below:

@Profiled(tag="tagName")
public void method2(){
    ... method body ...
}

Note: We need to include all jar of the AOP framework we choose and create the aspects for the @Profiled annotation to work.

RELATED ARTICLES

Logging Different Priority Level Messages to Separate Files

Log4j can be configured to publish different priority level messages in separate files; developers can log error messages in a separate file thus reducing the effort of searching errors in large files

View Article

Introduction to Logging with Log4J

Log4j is an open-source logging framework that helps developers to capture logging statements in java applications. It is fully configurable and can be configured using external configuration files.

View Article

Using Slf4J Facade with Log4j

Slf4j is a high level logging framework. Its serves as a facade and the actual logging is performed by the underlying logging framework which can be determined at runtime.

View Article