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.

36 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
  14. This blog is definitely entertaining additionally factual. I have picked up helluva helpful tips out of this amazing blog. I ad love to visit it again and again. Thanks!
    We are providing Background Removal Service with more than 15 years of experience.

    ReplyDelete
  15. So not only does a herbal Pro Keto Rx slimming patch level out your metabolism which means quicker and more efficient fat burning but also stop you from getting food cravings, so it acts as a dual action system, helping you lose weight faster.

    ReplyDelete
  16. Studies that compare the psychological characteristics of people who have successfully kept the weight off to people who have regained the weight, see clear differences between these two groups. For example, one study that looked at 28 obese women who had lost weight but


    Number One Keto

    ReplyDelete
  17. Weight problems are Keto Shred Biotic Immunity Booster the results of a condition of an individual's body exceeding the very least of 10% of the perfect body weight.

    ReplyDelete
  18. cardiovascular exercise that you can, following the completion of your body training exercises. Start yourself at ten minutes and work your way up to thirty minutes. This is the preparation step necessary for a successful Phase II of your healthy weight loss and quick weight loss.
    Keto Shred Biotic Immunity Booster

    ReplyDelete
  19. it will be and you'll be Keto Shred Biotic Immunity Booster more successful. The most important tool is knowledge. If you want to burn fat fast you will need to know how to do it properly so that you can achieve not only quick, but also long lasting results.

    ReplyDelete
  20. However with this type of PuriGlow Cream face lift treatment you should know that you will not get overnight result. Any product that promises overnight result is misleading.

    ReplyDelete
  21. The rest of the world is Fresh Prime Keto keeping pace pound for pound. As a species, we are getting steadily fatter, day by day, year by year. This is not just a question of vanity.

    ReplyDelete
  22. your belly fat. Once Xtreme Keto Boost I reached that plateau in my weight loss journey, nothing I did seemed to matter until I discovered these 5 fat burning foods.

    ReplyDelete
  23. which stores excess caloric Electro Keto energy for use in times of famine. Unfortunately our genetically programmed survival mechanism leads to failure for the majority of people trying to lose weight.

    ReplyDelete
  24. Well known for its nature of Cylophin RX increasing sexual performance even if the consumer has erectile dysfunction. This power herb can give you awesome result that you can have several orgasms within the night.

    ReplyDelete
  25. You may have never dreamed Fresh Prime Keto that there are fat burning foods which could cause natural weight loss and keep you from needing to spend hours in the gym trying to get rid of your belly fat. Once I reached that plateau in my weight loss journey, nothing I did seemed to matter until I discovered these 5 fat burning foods.

    ReplyDelete
  26. fulfilling her needs, it never hurts to do increase your penis size... well, at least it won't if you know the proper way of doing so.
    Empowered x Energy

    ReplyDelete
  27. By increasing androgenic effects Formax Lean Male Enhancement and Formax Lean Male Enhancement dramatically increasing testosterone, Tongkat Ali increases sexual arousal and motivation and frequency of sexual activity.

    ReplyDelete
  28. You may have never dreamed that there Reliant Keto are fat burning foods which could cause natural weight loss and keep you from needing to spend hours in the gym trying to get rid of your belly fat. Once I reached that plateau in my weight loss journey, nothing I did seemed to matter until I discovered these 5 fat burning foods.

    ReplyDelete
  29. These include such ingredients such as turkey, Reliant Keto quality carbohydrates, tuna, fruits and oatmeal to name a few. Proteins like the onces mentioned above and carbohydrates should be eaten together in every meal and they should be in the right balance to lose weight.

    ReplyDelete
  30. more calories then you consume the well accepted Befit Keto Cut will cause you to lose weight. To some degree, they all work: Atkins-style, no carb diets, low fat high carb diets, all manner of fad diets - it simply does not matter in the short term.

    ReplyDelete
  31. Here in this article we are going Viadine Male Enhancement to go over a few of my favourite natural male enhancement tips. However, before I get into it, it's probably quite important for you to recognise that being the writer of literally hundreds and hundreds of male enhancement articles and blog posts.

    ReplyDelete
  32. Now, you don't need to Bio Jolt Male Enhancement gulp down a gallon of OJ every day as it does have tons of sugars in it, but do a little analysis and take a look at the many fruits on the market which are rich in Vitamin C which will help bring about natural.

    ReplyDelete
  33. The solutions for weight loss before might Keto Now Real not be so effective with today's lifestyle. If you're overweight, there's not doubt you'd like to start losing belly fat. Here are some basic guidelines to help you get started.

    ReplyDelete