perf4j @Profiled annotation not working

Perf4j

This is a performance analysis and checking plugin for application. It can be integrated with spring using spring AOP. It creates a log file that is give to a parser to analyse and produce relevant information. It can provide average,mean, std deviation by default.For more general information please check http://perf4j.codehaus.org/index.html

How to setup Perf4j. For normal setup you just need to add perf4j jar and create StopWatch instance for every code sniplet you want to monitor.

StopWatch stopWatch= new StopWatch(“snipletTagName”)…//{your code sniplet}…stopwatch.stop();

This will create perf4j monitor and you will get logg information on the console.

Main purpose of this documentation is to have a setup by setup understanding of integrating perf4j with spring.

1.Add all of the below Jar files.

   1.perf4j-0.9.16-slf4jonly.jar   2.aspectjweaver-1.6.12.jar   3.aopalliance-1.0.jar   4.commons-logging-1.1.1.jar   5.logback-classic-1.0.7.jar   6.logback-core-1.0.7.jar   7.slf4j-api-1.7.1.jar   8.perf4j-0.9.16.jar   9.aspectjrt-1.6.1.jar   10.commons-jexl-1.1.jar   11.asm-1.5.3.jar   12.cglib-2.1_3.jar

Make sure you have all these jars in your classpath along with spring libraries.

2.create your own logback.xml that will be used by perf4j implicitlythe content of the logback.xml will be

<configuration>    <appender name="perf4jFileAppender"        class="ch.qos.logback.core.rolling.RollingFileAppender">        <File>logs/perf4j.log</File>        <encoder>            <Pattern>%date %-5level [%thread] %logger{36} [%file:%line] %msg%n            </Pattern>        </encoder>        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">            <FileNamePattern>logs/perf4j.%d{yyyy-MM-dd}.log</FileNamePattern>        </rollingPolicy>    </appender>    <appender name="CoalescingStatistics"        class="org.perf4j.logback.AsyncCoalescingStatisticsAppender">        <param name="TimeSlice" value="1" />                <appender-ref ref="perf4jFileAppender" />           </appender>    <appender name="RootConsoleAppender" class="ch.qos.logback.core.ConsoleAppender">        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">            <level>debug</level>        </filter>        <layout class="ch.qos.logback.classic.PatternLayout">            <pattern>%date %-5level [%thread] %logger{36} [%file:%line] %msg%n            </pattern>        </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="DEBUG" />        <appender-ref ref="CoalescingStatistics" />        <appender-ref ref="perf4jFileAppender" />        <appender-ref ref="RootConsoleAppender" />    </logger></configuration>

3.In your spring configuration file you need to add aspectj tag that will enable @Profiled annotation of perf4j.

(Note: What is @Profiled annotation?: you will add this tag to all the methods in all the classes that are called from spring instance or use dependency injection. The object basically should be spring context registered and the method should be invoked by the object that are registered in spring context. I wasted one day thinking why my method was not logged then I realized that the object I tested was not part of spring context.

OK, the code that you need to add to spring configuration xml is

<!-- this is my spring-context.xml --><beans>    <aop:aspectj-autoproxy>        <aop:include name="timingAspect" />    </aop:aspectj-autoproxy>    <bean id="timingAspect" class="org.perf4j.slf4j.aop.TimingAspect" /><!-- this is the class that will be registered with the spring and now we can get this class and call the method that we need to monitor-->    <bean class="com.perf4jexample.Test" /></beans>

4.Create the Test class that will implement @Profiled annotation.

public class Test {    private String testVal;    public Test() {        // TODO Auto-generated constructor stub    }    @Profiled    public void testing() {        System.out.println("testt" );    }    public String getTestVal() {        return testVal;    }    public void setTestVal(String testVal) {        this.testVal = testVal;    }}

5.Ok now you have setup every thing just thing remains is test class that will start spring context and with it load perf4j.

public class Test(){public static void main(){        AbstractApplicationContext context = new ClassPathXmlApplicationContext(                "spring-context.xml");        context.start();        Test bean = context.getBean(Test.class);        bean.testing();}

I hope by following these setups you should be able to perf4j console appender to display one line on console.

Perf4j Monitoring command on the log:

For Generating Performance statistical information execute on you logger path

java -jar perf4j-0.9.16.jar myLogger.log

For Generating Graphs

java -jar perf4j-0.9.16.jar --graph perfGraphs.out myLogger.log

I hope this tutorial helps you to integrated Spring, perf4j, logback with Profiled annotation.

Try adding <aop:include name="timingAspect"/> inside the <aop:aspectj-autoproxy/>.

Can you also confirm that you are invoking sendMessage on an object that is retrieved from the spring application context (using getBean or injected as a dependency).

Here I have two ways to make perf4j @Profiled work on spring boot project. Precondition is adding below dependencies

"org.aspectj:aspectjweaver","org.perf4j:perf4j:0.9.16","commons-jexl:commons-jexl:1.1","cglib:cglib:3.2.1",

For normal spring project, probably need to add little more dependencies like spring-aop, aopalliance... those looks included in spring-boot-starter-parent

1. Java Configuration

This is simplest way and mostly works, but I found that somehow not working on spring-data JpaRepository method. It just provides org.perf4j.log4j.aop.TimingAspect bean and do aspectj autoproxing. Same way like xml configuration provided by other people above

@Configuration@EnableAspectJAutoProxypublic class PerformanceConfig {    @Bean    public TimingAspect timingAspect() {        return new TimingAspect();    }}

2. Provide Your own Aspect

In this way, the @Profiled annotated spring-data repository interface methods also work fine. But the downside of this is ignoring the tag given in @Profiled(tag='some tag') and using the joinPoint method name as tag.

@Aspect@Componentpublic class PerformanceTracker {    @Around(value="execution(@org.perf4j.aop.Profiled * com.mypackage..*(..))")    public Object checkPerformance(ProceedingJoinPoint pjp) throws Throwable {        StopWatch stopWatch = new Log4JStopWatch(pjp.getSignature().toShortString());        Object result = pjp.proceed();        stopWatch.stop();        return result;    }}