Perf4J

When compiling using AspectJ's ajc compiler, bad bytecode would get generated that would cause this error:

Exception in thread "main" java.lang.AbstractMethodError: org.perf4j.aop.AbstractTimingAspect.hello(Ljava/lang/String;Ljava/lang/String;)V
at org.perf4j.aop.AbstractTimingAspect.ajc$inlineAccessMethod$org_perf4j_aop_AbstractTimingAspect$org_perf4j_aop_AbstractTimingAspect$hello(AbstractTimingAspect.java:1)
at org.perf4j.aop.AbstractTimingAspect.doPerfLogging(AbstractTimingAspect.java:57)
at ProfiledExample.logFailuresSeparatelyExample(ProfiledExample.java:83)
at ProfiledExample.main(ProfiledExample.java:12)

It turns out this was caused by this bug in AspectJ (which has, erroneously, been closed):

https://bugs.eclipse.org/bugs/show_bug.cgi?id=97481

In my debugging I found that in some cases ajc generates "inline" methods, like so (from javap output - see the ajc$inlineAccessMethods at the bottom):

public abstract class org.perf4j.aop.AbstractTimingAspect extends java.lang.Object{
public org.perf4j.aop.AbstractTimingAspect();
public java.lang.Object doPerfLogging(org.aspectj.lang.ProceedingJoinPoint, org.perf4j.aop.Profiled) throws java.lang.Throwable;
protected java.lang.String getStopWatchTag(org.perf4j.aop.Profiled, org.aspectj.lang.ProceedingJoinPoint, java.lang.Object, java.lang.Throwable);
protected java.lang.String getStopWatchMessage(org.perf4j.aop.Profiled, org.aspectj.lang.ProceedingJoinPoint, java.lang.Object, java.lang.Throwable);
protected java.lang.String evaluateJexl(java.lang.String, java.lang.Object[], java.lang.Object, java.lang.Object, java.lang.Throwable);
protected org.apache.commons.jexl.Expression getJexlExpression(java.lang.String) throws java.lang.Exception;
protected abstract org.perf4j.LoggingStopWatch newStopWatch(java.lang.String, java.lang.String);
public static java.lang.String ajc$inlineAccessMethod$org_perf4j_aop_AbstractTimingAspect$org_perf4j_aop_AbstractTimingAspect$getStopWatchTag(org.perf4j.aop.AbstractTimingAspect, org.perf4j.aop.Profiled, org.aspectj.lang.ProceedingJoinPoint, java.lang.Object, java.lang.Throwable);
public static org.perf4j.LoggingStopWatch ajc$inlineAccessMethod$org_perf4j_aop_AbstractTimingAspect$org_perf4j_aop_AbstractTimingAspect$newStopWatch(org.perf4j.aop.AbstractTimingAspect, java.lang.String, java.lang.String);
public static java.lang.String ajc$inlineAccessMethod$org_perf4j_aop_AbstractTimingAspect$org_perf4j_aop_AbstractTimingAspect$getStopWatchMessage(org.perf4j.aop.AbstractTimingAspect, org.perf4j.aop.Profiled, org.aspectj.lang.ProceedingJoinPoint, java.lang.Object, java.lang.Throwable);
}

It turns out I was able to work around this problem simply by changing this line in AbstractTimingAspect from:

LoggingStopWatch stopWatch = newStopWatch(profiled.logger(), profiled.level());

to

LoggingStopWatch stopWatch = newStopWatch(profiled.logger() + "", profiled.level());

For whatever reason adding the empty string causes ajc to NOT generate those faulty inline methods.

One other comment I wanted to add to this issue, because I'm guessing people may look here when they see "NoSuchMethodError: aspectOf()" errors when running profiled code.

From a recent email thread in response to a user who was compiling with ajc but then getting the NoSuchMethodError: aspectOf() when running with perf4j-0.9.10-log4jonly.jar in the classpath at runtime:

I think I understand what's going on. Note that we do NOT compile any of the perf4j jars with ajc - they are all just compiled with javac. If you review the example from the dev guide, note what's going on ( from http://perf4j.codehaus.org/devguide.html#Using_the_AspectJ_Compiler_to_Integrate_Timing_Aspects_at_Compile_Time ):

----------
2. Run the ajc compiler to weave the timing aspects into the ProfiledExample class (assumes the $ASPECTJ_DIR environment variable points to your AspectJ tools installation directory):

$ASPECTJ_DIR/bin/ajc -classpath $ASPECTJ_DIR/lib/aspectjrt.jar -1.5 -inpath perf4j-0.9.10-log4jonly.jar -outjar profiledExampleWoven.jar ProfiledExample.java

This will create a new jar named profiledExampleWoven.jar that includes the ProfiledExample class with the log4j TimingAspects integrated to execute around the methods with the Profiled annotation.
3. Execute the example using java, being sure to include the required dependencies in the classpath. Note that the perf4j-0.9.10-log4jonly.jar is NOT in the classpath, as those classes have been incorporated into profiledExampleWoven.jar:

java -cp .:profiledExampleWoven.jar:$ASPECTJ_DIR/lib/aspectjrt.jar:log4j-1.2.14.jar:commons-jexl-1.1.jar:commons-logging-1.0.3.jar ProfiledExample
----------

The important thing to note is the comment from step 3. The perf4j-0.9.10-log4jonly.jar is not included at runtime. Instead, the ajc-compiled versions of its aspects are included in the output jar (this is how ajc uses the -inpath and -outjar options).

Note I haven't used the Maven AspectJ plugin, but I would very much like to simplify the weaving process (and improve the doc) so if you send me your setup I should be able to help you out.

Thanks,
Alex