perf4j @Profiled annotation not working

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.TimingA开发者_开发知识库spect"/>
<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?

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.

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
@EnableAspectJAutoProxy
public 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
@Component
public 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;
    }
}

The reason why it could not work is that the profiled method is in the parent class of the Spring-bean. I can tell it by looking at your bean name: WscClientBase. I assume that this is base class from which you have many children classes.

After some research time I found very important note in Spring documentation about @Transactional and @Cacheable.

• http://docs.spring.io/spring-framework/docs/current/spring-framework-reference/html/transaction.html#transaction-declarative-annotations. Check “Method visibility and @Transactional” block.
• http://docs.spring.io/spring/docs/current/spring-framework-reference/html/cache.html#cache-annotation-enable. Check “Method visibility and cache annotations”

In both cases they say things like this:

“When using proxies, you should apply the <> annotations only to methods with public visibility. If you do annotate protected, private or package-visible methods with these annotations, no error is raised, but the annotated method does not exhibit the configured caching settings. Consider the use of AspectJ (see below) if you need to annotate non-public methods as it changes the bytecode itself.”

And below…

“Spring recommends that you only annotate concrete classes (and methods of concrete classes) with the @Cache* annotation, as opposed to annotating interfaces. You certainly can place the @Cache* annotation on an interface (or an interface method), but this works only as you would expect it to if you are using interface-based proxies. The fact that Java annotations are not inherited from interfaces means that if you are using class-based proxies (proxy-target-class="true") or the weaving-based aspect ( mode="aspectj"), then the caching settings are not recognized by the proxying and weaving infrastructure, and the object will not be wrapped in a caching proxy, which would be decidedly bad.”

I assume that @Profiled use similar weaving mechanism therefore you can't put @Profiled on any method in parent classes. As a matter of fact I had similar issue in my application: I had @Profiled and @Cacheable in parent class and none of those worked: I didn't see any records in my Perf4J log and cache wasn't updated. When I moved @Profiled into methods of children-classes I started seeing the records in the perf4j.log.

put config below in your "servlet-context-config.xml" .have fun!

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

For people who have this type of problem they can check that there is not in spring logs (level info), messages like it " is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)".