Using perf4j to time methods

Perf4j is a great way to instrument your code to find out how long your methods are taking to execute.  I wanted a way to annotate my method and not have to pollute the code with startTimer, endTimer stuff.

Enter Perf4j's annotation based approach, implemented with aspectj AOP framework. Perfect!

Add the following maven dependencies to your pom

      <dependency>  
       <groupId>org.perf4j</groupId>  
       <artifactId>perf4j</artifactId>  
       <version>0.9.16</version>  
     </dependency>  
     <dependency>  
      <groupId>org.aspectj</groupId>  
      <artifactId>aspectjrt</artifactId>  
      <version>1.6.7</version>  
     </dependency>  
     <dependency>  
       <groupId>aspectj</groupId>  
       <artifactId>aspectjweaver</artifactId>  
       <version>1.5.4</version>  
     </dependency>  
     <dependency>  
       <groupId>commons-jexl</groupId>  
       <artifactId>commons-jexl</artifactId>  
       <version>1.1</version>  
     </dependency>  

Create the aop.xml file in the main/resources/META-INF/ folder.

 <?xml version="1.0" encoding="UTF-8"?>  
 <aspectj>  
  <!--  
   We only want to weave in the log4j TimingAspect into the @Profiled classes.  
   Note that Perf4J provides TimingAspects for the most popular Java logging  
   frameworks and facades: log4j, java.util.logging, Apache Commons Logging  
   and SLF4J. The TimingAspect you specify here will depend on which logging  
   framework you wish to use in your code.  
  -->  
  <aspects>  
   <aspect name="org.perf4j.log4j.aop.TimingAspect"/>  
   <!-- if SLF4J/logback use org.perf4j.slf4j.aop.TimingAspect instead -->  
  </aspects>  
  <weaver options="-verbose -showWeaveInfo">  
   <!--  
    Here is where we specify the classes to be woven. You can specify package  
    names like com.company.project.*  
   -->  
   <include within="com.yourpackage.*"/>  
   <include within="org.perf4j.log4j.aop.*"/>  
  </weaver>  
 </aspectj>  

Add the following to your log4j file

 <!-- 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="600000"/>  
     <appender-ref ref="fileAppender"/>  
     <!--  
      Note how the GraphingStatisticsAppenders have been attached to the  
      CoalescingStatistics here.  
     -->  
     <appender-ref ref="graphExecutionTimes"/>  
     <appender-ref ref="graphExecutionTPS"/>  
   </appender>  
   <!-- This file appender is used to output aggregated performance statistics -->  
   <appender name="fileAppender" class="org.apache.log4j.FileAppender">  
     <param name="File" value="/logs/perfStats.log"/>  
     <layout class="org.apache.log4j.PatternLayout">  
       <param name="ConversionPattern" value="%m%n"/>  
     </layout>  
   </appender>  
   <!--  
    This first GraphingStatisticsAppender graphs Mean execution times for the  
    firstBlock and secondBlock tags  
   -->  
   <appender name="graphExecutionTimes"  
        class="org.perf4j.log4j.GraphingStatisticsAppender">  
     <!-- Possible GraphTypes are Mean, Min, Max, StdDev, Count and TPS -->  
     <param name="GraphType" value="Mean"/>  
     <!-- The tags of the timed execution blocks to graph are specified here -->  
     <param name="TagNamesToGraph" value="firstBlock,secondBlock"/>  
     <appender-ref ref="graphsFileAppender"/>  
   </appender>  
   <!--  
    This second GraphingStatisticsAppender graphs transactions per second  
    for the firstBlock and secondBlock tags  
   -->  
   <appender name="graphExecutionTPS"  
        class="org.perf4j.log4j.GraphingStatisticsAppender">  
     <param name="GraphType" value="TPS"/>  
     <param name="TagNamesToGraph" value="firstBlock,secondBlock"/>  
     <appender-ref ref="graphsFileAppender"/>  
   </appender>  
   <!--  
    This file appender is used to output the graph URLs generated  
    by the GraphingStatisticsAppenders  
   -->  
   <appender name="graphsFileAppender" class="org.apache.log4j.FileAppender">  
     <param name="File" value="perfGraphs.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>  

Add the @Profiled annotation to your code and off you go!
A file called perfStats.log is created with the stats.  There are parameters that can be tuned and graph based appenders that you can use as well.  For more details please check out perf4j Developer Guide

Update: 

If you are deploying to tomcat; to enable load time weaving; you will need to add 

-javaagent:<location_of_aspectjweaver.jar> to JAVA_OPTIONS.