Debugging Application Performance With Perf4j

Performance is one of the main aspect that we all need to consider when implementing systems. Today's world of Service Oriented Architectures and distributed applications, detecting performance bottleneck is really a difficult task.

If someone asked "Why is my web app slow ?"  this requires investigation multiple components and execution paths, and it requires detailed performance data from all of the application components.

In order to get the performance data one of the most common practice is to get the execution time for given path. System.currentTime() is one approach to do this. But we need to have some custom mechanism to aggregate these results to analyze further.

Perf4j is an open source performance logging framework that specially design to solve the above scenario. Its a,

• Simple stop watch mechanism to time statements.
• Command line tool to generate aggregate statistics 
• Can integrate with log4j
• Provides @Profile annotation to use it with Aspects.

You can find more details explanation in here and here.

But here I will drive through with some detailed example to understand,

• How to integrate perf4j with log4j
• How to configure log4j.xml to use separate log file for performance results
• Commands to aggregate performance log data

As usual you can find the sample code here.

https://github.com/rajithd/per4j-sample

First we will create a sample maven project and then create a class called PerformanceMonitor to hold the stop watch.
Add per4j and log4j dependencies to pom.xml

 <dependencies>  
     <dependency>  
       <groupId>org.perf4j</groupId>  
       <artifactId>perf4j</artifactId>  
       <version>${perf4j.version}</version>  
     </dependency>  
     <!-- Logging -->  
     <dependency>  
       <groupId>org.slf4j</groupId>  
       <artifactId>slf4j-api</artifactId>  
       <version>${slf4j.version}</version>  
     </dependency>  
     <dependency>  
       <groupId>org.slf4j</groupId>  
       <artifactId>slf4j-log4j12</artifactId>  
       <version>${slf4j.version}</version>  
     </dependency>  
   </dependencies>  

PerformanceMonitor.java

 public class PerformanceMonitor {  
   private static final ThreadLocal<StopWatch> WATCH = new ThreadLocal<StopWatch>() {  
     @Override  
     protected StopWatch initialValue() {  
       return new Log4JStopWatch(Logger.getLogger("instrument.org.perf4j.TimingLogger"));  
     }  
   };  
   public static void start(String tag) {  
     WATCH.get().start(tag);  
   }  
   public static void stop(String tag) {  
     WATCH.get().stop(tag);  
   }  
 }  

As you can clearly see I used this as a ThreadLocal instance because I'm expecting to run this application in multi-threaded environment.

Then configure log4j.xml

 <?xml version="1.0" encoding="UTF-8" ?>  
 <!DOCTYPE log4j:configuration SYSTEM  
     " http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/xml/doc-files/log4j.dtd">  
 <log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">  
   <appender name="console" class="org.apache.log4j.ConsoleAppender">  
     <layout class="org.apache.log4j.PatternLayout">  
       <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss} %-5p %t %c{1}:%L - %m%n"/>  
     </layout>  
   </appender>  
   <appender name="trace" class="org.apache.log4j.DailyRollingFileAppender">  
     <param name="File" value="trace.log"/>  
     <param name="Threshold" value="debug"/>  
     <param name="DatePattern" value="'.'yyyy-MM-dd"/>  
     <layout class="org.apache.log4j.PatternLayout">  
       <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss} %-5p %t %c{1}:%L - %m%n"/>  
     </layout>  
   </appender>  
   <appender name="error" class="org.apache.log4j.DailyRollingFileAppender">  
     <param name="File" value="logs/vetstoria-oltp-error.log"/>  
     <param name="Threshold" value="error"/>  
     <param name="DatePattern" value="'.'yyyy-MM-dd"/>  
     <layout class="org.apache.log4j.PatternLayout">  
       <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss} %-5p %t %c{1}:%L - %m%n"/>  
     </layout>  
   </appender>  
   <appender name="statistics" class="org.apache.log4j.FileAppender">  
     <param name="File" value="perf.log"/>  
     <param name="Append" value="false"/>  
     <layout class="org.apache.log4j.PatternLayout">  
       <param name="ConversionPattern" value="%m%n"/>  
     </layout>  
   </appender>  
   <logger name="org.perf4j.TimingLogger">  
     <level value="info"/>  
     <appender-ref ref="statistics"/>  
   </logger>  
   <logger name="com.rd">  
     <level value="debug"/>  
     <appender-ref ref="console"/>  
     <appender-ref ref="trace"/>  
     <appender-ref ref="error"/>  
   </logger>  
   <logger name="instrument">  
     <level value="info"/>  
     <appender-ref ref="console"/>  
     <appender-ref ref="statistics"/>  
   </logger>  
 </log4j:configuration>  

Check the "org.per4j.TimingLogger" and "instrument" loggers carefully.  You can see the relevant appender called "statistics"  that will redirect output to a file called perf.log

App.java is pretty straightforward.

 public class App {  
   private static final Logger LOGGER = Logger.getLogger(App.class);  
   public static void main(String[] args) throws InterruptedException {  
     LOGGER.info("Starting .....");  
     PerformanceMonitor.start("METHOD1");  
     method1();  
     PerformanceMonitor.stop("METHOD1");  
     PerformanceMonitor.start("METHOD2");  
     method2();  
     PerformanceMonitor.stop("METHOD2");  
     LOGGER.info("Completed. Please check the perf.log file for time logging");  
   }  
   private static void method1() throws InterruptedException {  
     Thread.sleep(5000);  
   }  
   private static void method2() throws InterruptedException {  
     Thread.sleep(2000);  
   }  
 }  

Then run the App.java main method and this will create two log files in same hierarchy. All the performance related logs populate into a file called perf.log.

When you inspect the perf.log file you can see the following output.

 start[1444722158471] time[5000] tag[METHOD1]  
 start[1444722163472] time[2000] tag[METHOD2]  

To get aggregate results,

1. Download per4j jar. (http://mvnrepository.com/artifact/org.perf4j/perf4j/0.9.16)
2. Run following command

 java -jar <perf4j.location>/perf4j-0.9.16.jar --timeslice 3000000000 --format csv perf.log -o output.csv  

Open up the output.csv and you can see the aggregated performance results.