[aspectj-users] Aspect not being applied

["Leyzerzon, Simeon " <simeon.leyzerzon@xxxxxxxx>]

In Eclipse I'm seeing the following warning:

advice defined in com.xxxx.gdos.smart.applib.service.logging.MethodProfilingAspect has not been applied [Xlint:adviceDidNotMatch]

for the following aspect:


@Aspect
public class MethodProfilingAspect {

        private final static Log log = LogFactory.getLog(MethodProfilingAspect.class);

        @Pointcut("execution(* *..*Dao+.*(..))")
    public void daoExecution(){}

        @Around("daoExecution()")
        public Object profile(ProceedingJoinPoint joinpoint) throws Throwable {

                final StopWatch stopWatch = new StopWatch();
                stopWatch.start();
                Object methodResult = null;
                try {
                        methodResult = joinpoint.proceed();
                } finally {
                        stopWatch.stop();
                }
                final long millis = stopWatch.getTime();
                final BigDecimal seconds = new BigDecimal(millis).divide(
                                new BigDecimal(DateUtils.MILLIS_PER_SECOND),
                                BigDecimal.ROUND_HALF_UP);

                if (log.isInfoEnabled()) {
                        log.info("Method Invocation ["
                                        + joinpoint.getTarget().getClass().getName() + "."
                                        + joinpoint.getSignature().getName() + "] Total Time: "
                                        + seconds + "(seconds) " + millis + "(millis)");
                }
                return methodResult;
        }

}

and eventually the advise doesn't get applied, which is confirmed from this JUnit output:

2009-10-13 14:09:56,680 (ExecutiveSummaryGridCommonSP Line:50) SQL = P_ENTL_HC_ANLS_GET_SMRY_VW
2009-10-13 14:09:56,680 (ExecutiveSummaryGridCommonSP Line:156) Compiled stored procedure. Call string is [{call P_ENTL_HC_ANLS_GET_SMRY_VW(?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]
2009-10-13 14:09:56,696 (ExecutiveSummaryGridCommonSP Line:342) RdbmsOperation with SQL [P_ENTL_HC_ANLS_GET_SMRY_VW] compiled
2009-10-13 14:10:00,477 (ExecutiveSummaryGridCommonSP Line:50) SQL = P_ENTL_HC_ANLS_GET_SMRY_VW
2009-10-13 14:10:00,477 (ExecutiveSummaryGridCommonSP Line:156) Compiled stored procedure. Call string is [{call P_ENTL_HC_ANLS_GET_SMRY_VW(?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]
2009-10-13 14:10:00,477 (ExecutiveSummaryGridCommonSP Line:342) RdbmsOperation with SQL [P_ENTL_HC_ANLS_GET_SMRY_VW] compiled

However, when configuring a similar advise via Spring, like so:

<aop:config>
 <aop:pointcut id="getAllDaoExPointcut"
        expression="execution(* *..*Dao+.*(..))" />
 <aop:advisor id="methodTimingAdvisor"
  advice-ref="methodTimingAdvice" pointcut-ref="getAllDaoExPointcut" />
</aop:config>

<bean id="methodTimingAdvice" class="com.xxx.gdos.smart.applib.service.logging.MethodTimingInterceptor" />


with the following advise:

public class MethodTimingInterceptor implements MethodInterceptor {

        private final static Log log = LogFactory.getLog(MethodTimingInterceptor.class);

        public Object invoke(final MethodInvocation methodInvocation) throws Throwable {

                final StopWatch stopWatch = new StopWatch();
                stopWatch.start();
                Object methodResult = null;
                try {
                        methodResult = methodInvocation.proceed();
                } finally {
                        stopWatch.stop();
                }
                final long millis = stopWatch.getTime();
                final BigDecimal seconds = new BigDecimal(millis).divide(
                                new BigDecimal(DateUtils.MILLIS_PER_SECOND),
                                BigDecimal.ROUND_HALF_UP);

                if (log.isInfoEnabled()) {
                        log.info("Method Invocation ["
                                        + methodInvocation.getThis().getClass().getName() + "."
                                        + methodInvocation.getMethod().getName() + "] Total Time: "
                                        + seconds + "(seconds) " + millis + "(millis)");
                }
                return methodResult;
        }
}


I am seeing a different output from the same JUnit test reflect that the advise has been weaved in:

2009-10-13 14:11:58,770 (ExecutiveSummaryGridCommonSP Line:50) SQL = P_ENTL_HC_ANLS_GET_SMRY_VW
2009-10-13 14:11:58,786 (ExecutiveSummaryGridCommonSP Line:156) Compiled stored procedure. Call string is [{call P_ENTL_HC_ANLS_GET_SMRY_VW(?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]
2009-10-13 14:11:58,786 (ExecutiveSummaryGridCommonSP Line:342) RdbmsOperation with SQL [P_ENTL_HC_ANLS_GET_SMRY_VW] compiled
2009-10-13 14:12:00,176 (MethodTimingInterceptor Line:41) Method Invocation [com.citi.gdos.iris.gma.dao.FooGmaDao.getExecutiveSummaryDatagridsDaoBuffer] Total Time: 1(seconds) 1422(millis)
2009-10-13 14:12:00,176 (MethodTimingInterceptor Line:41) Method Invocation [$Proxy9.getExecutiveSummaryDatagridsDaoBuffer] Total Time: 1(seconds) 1422(millis)
2009-10-13 14:12:00,176 (ExecutiveSummaryGridCommonSP Line:50) SQL = P_ENTL_HC_ANLS_GET_SMRY_VW
2009-10-13 14:12:00,176 (ExecutiveSummaryGridCommonSP Line:156) Compiled stored procedure. Call string is [{call P_ENTL_HC_ANLS_GET_SMRY_VW(?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]
2009-10-13 14:12:00,176 (ExecutiveSummaryGridCommonSP Line:342) RdbmsOperation with SQL [P_ENTL_HC_ANLS_GET_SMRY_VW] compiled
2009-10-13 14:12:00,317 (MethodTimingInterceptor Line:41) Method Invocation [com.citi.gdos.iris.gma.dao.FooGmaDao.getExecutiveSummaryDatagridsDaoBuffer] Total Time: 0(seconds) 141(millis)
2009-10-13 14:12:00,317 (MethodTimingInterceptor Line:41) Method Invocation [$Proxy9.getExecutiveSummaryDatagridsDaoBuffer] Total Time: 0(seconds) 141(millis)

Could someone please point me to the right direction as to what is missing.

TIA,
Simeon