perf4j @Profiled annotation not working

Question

I have gone thru the below link from perf4J site and have done same to same: http://perf4j.codehaus.org/devguide.html#Using_Spring_AOP_to_Integrate_Timing_Aspects

Added the following in my spring.xml.

<aop:aspectj-autoproxy/>
<bean id="timingAspect" class="org.perf4j.log4j.aop.TimingAspect"/>
<bean id="wscClientBase" class="com.xyz.csa.core.common.WscClientBase"/>

In class WscClientBase I have the following method with @Profiled annotation.

@Profiled(tag = "SOAPCALLTEST")
public Object sendMessage(Object message) {
    String msg = message.toString();
    if (msg.indexOf(' ') > 1) {
        msg = msg.substring(1, msg.indexOf(' '));
    }
    try {
        Object ret = marshalSendAndReceive(message);
        return ret;
    } catch (RuntimeException ex) {
        throw ex;
    }
}

I dont see the perf4j TimingLogger statements in the application log. However if I use it obtrusively (without annotation) as below, I see the log statements successfully.

public Object sendMessage(Object message) {
    String msg = message.toString();
    if (msg.indexOf(' ') > 1) {
        msg = msg.substring(1, msg.indexOf(' '));
    }
    StopWatch stopWatch = new Slf4JStopWatch();
    try {
        Object ret = marshalSendAndReceive(message);
        stopWatch.stop("PERF_SUCCESS_TAG", msg);
        return ret;
    } catch (RuntimeException ex) {
        stopWatch.stop("PERF_FAILURE_TAG", msg);
        throw ex;
    }
}

Am I missing something?

Answer 1

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 implicitly the 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.

Answer 2

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).