Profiling Java Application using annotation

This blog will provide details of measuring a performance of a code snippet while developing. This is will very handy to developer to quickly measure the performance of a method while unit testing.

Benefits:

While developing a feature a developer usually missed out performance parameter which is equally and important nonfunctional requirement.  Ideally a developer must make it as a practice to test performance of their code along with unit testing and improved it if it is not fall under acceptance criteria. A quick measurement of performance is to check the elapse time of a method. Most of the time we monitor elapse time using System.currentTimeMillis method.  But for this we need to add unwanted statements in our code. Moreover along with elapse time sometime we also required some further information like mean, minimum, maximum, standard deviation and transactions per second over a set time span.

All above task for testing performance can be easily carried out by using perf4j API. It provides us some annotation placing which we can profile our code and can get statistic in log statement. We can turn off profiling any time by removing annotation. It is quicker method to profile code snippet along with unit testing.

How to use:

Integrating perf4j API with a project is very easy. Below are steps to integrate Perf4j with a maven project. 

Add following dependency to your pom.xml. If you are integrating in an existing project then you may have some of them already in your pom.xml

<dependency>         <groupId>org.perf4j</groupId>         <artifactId>perf4j</artifactId>         <version>0.9.16</version>         <scope>compile</scope>     </dependency>     <!-- if you use the log4j implementation of Perf4J, you must also include this dependency -->     <dependency>         <groupId>log4j</groupId>         <artifactId>log4j</artifactId>         <version>1.2.14</version>         <scope>compile</scope>     </dependency>     <!-- if you use the commons logging implementation of Perf4J, you must also include this dependency -->     <dependency>         <groupId>commons-logging</groupId>         <artifactId>commons-logging</artifactId>         <version>1.0.3</version>         <scope>compile</scope>     </dependency>     <!-- if you use the SLF4J implementation of Perf4J, you must also include this dependency -->     <dependency>         <groupId>org.slf4j</groupId>         <artifactId>slf4j-api</artifactId>         <version>1.5.6</version>         <scope>compile</scope>     </dependency>     <!-- if you use also use logback as the SLF4J underlying impl, you must also include this dependency -->     <dependency>         <groupId>ch.qos.logback</groupId>         <artifactId>logback-classic</artifactId>         <version>0.9.15</version>         <scope>compile</scope>         <optional>true</optional>     </dependency>     <!-- if you use the AOP functionality of Perf4J, you must also include these 2 dependencies -->     <dependency>         <groupId>org.aspectj</groupId>         <artifactId>aspectjrt</artifactId>         <version>1.6.1</version>         <scope>runtime</scope>     </dependency>     <dependency>         <groupId>commons-jexl</groupId>         <artifactId>commons-jexl</artifactId>         <version>1.1</version>         <scope>runtime</scope>     </dependency>     <!-- if you use Spring to manage the AOP funcionality, you must also include these 2 dependencies -->     <dependency>         <groupId>org.springframework</groupId>         <artifactId>spring</artifactId>         <version>2.0.6</version>         <scope>runtime</scope>     </dependency>     <dependency>         <groupId>cglib</groupId>         <artifactId>cglib</artifactId>         <version>2.2</version>         <scope>runtime</scope>     </dependency>     <dependency>                 <groupId>org.aspectj</groupId>                 <artifactId>aspectjweaver</artifactId>                 <version>1.6.11</version>     </dependency>

Add or append following spring configuration to project

<?xml version="1.0" encoding="UTF-8"?> <!-- Note how the aop namespace is defined in the top-level beans element --> <beans xmlns="http://www.springframework.org/schema/beans"        xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"        xmlns:aop="http://www.springframework.org/schema/aop"        xsi:schemaLocation="http://www.springframework.org/schema/beans                            http://www.springframework.org/schema/beans/spring-beans-3.0.xsd                            http://www.springframework.org/schema/aop                            http://www.springframework.org/schema/aop/spring-aop-3.0.xsd">     <aop:aspectj-autoproxy/>     <bean id="timingAspect" class="org.perf4j.log4j.aop.TimingAspect"/>     <!--       Because we included the aspectj-autoproxy element, Spring will automatically       create a proxy for this bean that runs the TimingAspect around any public       @Profiled methods on this bean.     -->     <bean id="performanceTester" class="com.vcjain.perf.PerformanceTester"/> </beans>

Add or append following log configuration

<?xml version="1.0" encoding="UTF-8" ?> <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd"> <log4j:configuration debug="false" xmlns:log4j="http://jakarta.apache.org/log4j/">     <!--       This default ConsoleAppender is used to log all NON perf4j messages       to System.out     -->     <appender name="console" class="org.apache.log4j.ConsoleAppender">         <layout class="org.apache.log4j.PatternLayout">             <param name="ConversionPattern" value="%-5p %c{1} - %m%n"/>         </layout>     </appender>     <!-- Perf4J appenders -->     <!--        This AsyncCoalescingStatisticsAppender groups StopWatch log messages        into GroupedTimingStatistics messages which it sends on the        file appender defined below     -->     <appender name="CoalescingStatistics"               class="org.perf4j.log4j.AsyncCoalescingStatisticsAppender">         <!--           The TimeSlice option is used to determine the time window for which           all received StopWatch logs are aggregated to create a single           GroupedTimingStatistics log. Here we set it to 10 seconds, overriding           the default of 30000 ms         -->         <param name="TimeSlice" value="10000"/>         <appender-ref ref="fileAppender"/>     </appender>     <!-- This file appender is used to output aggregated performance statistics -->     <appender name="fileAppender" class="org.apache.log4j.FileAppender">         <param name="File" value="profile.log"/>         <layout class="org.apache.log4j.PatternLayout">             <param name="ConversionPattern" value="%m%n"/>         </layout>     </appender>     <!-- Loggers -->     <!--       The Perf4J logger. Note that org.perf4j.TimingLogger is the value of the       org.perf4j.StopWatch.DEFAULT_LOGGER_NAME constant. Also, note that       additivity is set to false, which is usually what is desired - this means       that timing statements will only be sent to this logger and NOT to       upstream loggers.     -->     <logger name="org.perf4j.TimingLogger" additivity="false">         <level value="INFO"/>         <appender-ref ref="CoalescingStatistics"/>     </logger>     <!--       The root logger sends all log statements EXCEPT those sent to the perf4j       logger to System.out.     -->     <root>         <level value="INFO"/>         <appender-ref ref="console"/>     </root> </log4j:configuration>

With above configuration you are ready for profiling. Now add @Profiled annotation to the method which you want to profile and execute code. You will receive your statistic in your log file specified in logging configuration something like below

Performance Statistics   2013-08-30 13:07:10 - 2013-08-30 13:07:20 Tag                             Avg(ms)         Min         Max     Std Dev       Count profileTest                     2027.0        2027        2027         0.0           1

For non-maven project we can keep all dependency jars in the classpath. I have created a sample maven project to demonstrate use of Perf API. Please get the complete project from Git repository https://github.com/vcjain/perfapi.git. You can execute project using maven command mvn exec:java.