Pages

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.

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.

16 comments:

  1. Really Good blog post.provided a helpful information about debugging application performance.keep updating...
    Digital marketing company in Chennai

    ReplyDelete
  2. https://edutry.blogspot.in/2017/05/augmented-reality-for-products.html?showComment=1510748334817#c8070672859228630519

    ReplyDelete
  3. Hi dear, I like your post so much, and it is very good. Hope that we can communicate with each other. I want to introduce an aso services, I try it and I feel it is so good to us beginners.

    ReplyDelete
  4. This is an incredible rousing article.I am essentially satisfied with your great work.You put truly exceptionally accommodating data. Keep it up. Continue blogging. Hoping to perusing your next post.
    Brother And Sister Quotes
    Happy Birthday SMS

    ReplyDelete
  5. the difference format external hard drive windows 10 in price could be tangible damages. Your data is your data and it is characterized by this size. Unless you are planning on deleting large chunks of data, shrinking is not going to do much of anything.

    ReplyDelete
  6. Nice blog has been shared by you. it will be really helpful to many peoples who are all working under the technology.thank you for sharing this blog.

    software testing course in chennai

    ReplyDelete
  7. I believe there are many more pleasurable opportunities ahead for individuals that looked at your site.
    Aws Training in Chennai
    Advanced Aws Training in Chennai

    ReplyDelete
  8. Maxatron Plus do you want to be subjected to constant doctor visits and tests, take painful testosterone injections or would you rather use a natural enhancement pill to boost your testosterone levels?

    ReplyDelete
  9. Bionatrol Pro Enhance really expensive as well as inconvenient in some point because you have to wear these devices for about two to six hours everyday. This can be difficult for most men especially those who have active lifestyle.

    ReplyDelete
  10. Synergex 7 about their manhood, especially when they come to a point in their life when they feel they need to prove something. Most men want to enhance their male organ for sexual purposes:

    ReplyDelete
  11. Ryzex Male Enhancement hand involves your health, so it is vital that careful understanding and study of each of the options available be made before settling on one solution or a combination of many.

    ReplyDelete
  12. Keto Gedeon then eat 4-6 small meals during the day. The reason to this might be the fact that they get hungrier later on in the day, and might have a tendency to over eat during other meals of the day.

    ReplyDelete
  13. Super Fast Keto Boost Take joy in small progress. Acknowledge yourself when you have done little and consistent weight loss progresses. Do not be too harsh on

    ReplyDelete