search

astefanutti / metrics-aspectj

AspectJ integration for Dropwizard Metrics
Apache License 2.0
81 stars 39 forks source link

@Timed method on base class throws NullPointerException when class is extended #11

Closed carysyd closed 8 years ago

carysyd commented 8 years ago

Hi, metrics-aspectj developers

I have been using your library and found it very convenient to annotate a method to capture performance metrics. Recently I hit the wall when trying the extend a class that has annotated methods. Here's what I see:

@Metrics
public class Base {
    public void something_not_timed() {
        ...
   }
    @Timed(name="method1-ProcessTime")
    public void method1() {
       ...
    }
}

I have been using Base class in production without issue. Now I need to extend this class.

public class Derived extends Base {
    @Override
    public void something_not_timed() {
        ....
    }
}

As you can see, method1() is not overridden. But the problem is that whenever I use method1() in Derived class, I would get a NullPointerException in method1_aroundBody1$advice().

I'm not familiar with AspectJ so couldn't really figure out what I'm missing, any advice will be highly appreciated.

Thanks!

Regards, Cary

astefanutti commented 8 years ago

Hi Cary,

Thanks for the report. Each time an instance of a class annotated with @Metrics is created, the MetricAspect aspect executes and iterates over the declared methods to create the Timer instances for the @Timed annotated methods and put the created timers in a map: MetricAspect.aj#L43. Then, whenever these methods get called, the TimedAspect.aj#L26 kicks in and lookup for the corresponding timer in that map.

It looks like in you use case, the look up fails to find the timer in TimedAspect.aj#L28. So either the key used in MetricAspect.aj#L95 is different from the key used in the TimedAspect.aj#L28 or the MetricAspect isn't called as the @Metrics annotation is not declared @Inherited.

Would that be possible for you to create a PR with a test case in the envs/se module so that we can confirm which hypothesis is correct and eventually do the appropriate fix, which should be quite straightforward.

kriegaex commented 8 years ago

After having found Cary's question on StackOverflow, I tried to reproduce it and easily could:

I have just published GitHub demo repo. If you just perform mvn clean install exec:java you see the problem.

I have also forked your own repo and added some debug output to TimedAspect. If you build my metrics-aspectj fork with mvn clean install and change the dependency version in the demo project to 1.1-SNAPSHOT you will see this log output:

$ mvn clean install exec:java

[INFO] Scanning for projects...
[INFO]                                                                         
[INFO] ------------------------------------------------------------------------
[INFO] Building Java Application 0.0.1-SNAPSHOT
[INFO] ------------------------------------------------------------------------
(...)
[INFO] --- exec-maven-plugin:1.4.0:java (default-cli) @ java-app ---
#################
thisJoinPoint = execution(void de.scrum_master.app.Base.method1())
object = de.scrum_master.app.Base@24cb45bc
methodSignature = public void de.scrum_master.app.Base.method1()
object.timers = {public void de.scrum_master.app.Base.method1()=io.astefanutti.metrics.aspectj.AnnotatedMetric$IsPresent@67fec6b3}
object.timers.get(methodSignature) = io.astefanutti.metrics.aspectj.AnnotatedMetric$IsPresent@67fec6b3
object.timers.get(methodSignature).getMetric() = com.codahale.metrics.Timer@7ae827c2
timer = com.codahale.metrics.Timer@7ae827c2
#################
thisJoinPoint = execution(void de.scrum_master.app.Base.method1())
object = de.scrum_master.app.Derived@3b51c83f
methodSignature = public void de.scrum_master.app.Base.method1()
object.timers = {}
object.timers.get(methodSignature) = null
[WARNING] 
java.lang.reflect.InvocationTargetException
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.codehaus.mojo.exec.ExecJavaMojo$1.run(ExecJavaMojo.java:293)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.NullPointerException
    at de.scrum_master.app.Base.method1_aroundBody1$advice(Base.java:34)
    at de.scrum_master.app.Base.method1(Base.java:1)
    at de.scrum_master.app.Application.main(Application.java:15)
    ... 6 more
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
(...)

As you can see, for object = de.scrum_master.app.Derived@3b51c83f we get object.timers = {}. This seems to be the source of the problem.

Off-topic: By the way, I wonder why annotation @Timed is not @Inherited. I know it would not help with JVM limitations concerning method annotations, but at least it would cater for inheritance of this class-based annotation.

astefanutti commented 8 years ago

@kriegaex thanks a lot for the analysis.

That means that the MetricAspect is not executed and does not populate the object.timers map for the child class. This is logical since the @Metrics annotation is not declared @Inherited. Though I didn't anticipate that, while the MetricAspect and TimedAspect defines the same pointcut type, that are execution((@Metrics Profiled+).new(..)) and execution(@Timed !static * (@Metrics Profiled+).*(..)) respectively, the TimedAspect is called for the child class while the MetricAspect is not!

Obviously, the use case is legitimate. So the way to go would be to declare the @Metrics annotation @Inherited and then iterate over the class hierarchy in MetricAspect to discover Metrics annotations on declared methods in a similar way to what's been done in Metrics CDI here.

PS: the @Timed annotation is now declared @Inherited since Metrics version 3.1.0.

carysyd commented 8 years ago

@kriegaex Thanks for the help for the analysis and created the sample

@astefanutti It's great to know that you guys found the issue already. Would you mind if I ask if this is something quick to fix so I can pull the updated artifact from Maven central repo?

If this is going to take some time, could you please suggest a workaround while I wait for the fix? My "Derived" class is going to be used internally so even losing the Metrics capability is acceptable for now.

Thanks again!

astefanutti commented 8 years ago

@carysyd I'll try to work on it ASAP though that's not my priority at the moment. In the meantime, as a work-around, you can either:

Obviously, I encourage you to contribute directly to the project if these work-around aren't acceptable for you.

kriegaex commented 8 years ago

Overriding a method does not necessarily involve duplicating logic, because delegation to super is a better idea. It is ugly anyway, but that is why we call it a workaround. ;-)

astefanutti commented 8 years ago

@kriegaex calling super would execute the advice and produce the error, hence my point.

kriegaex commented 8 years ago

Oh, that's a gotcha. I have not actually tried, just thought out loud. Sorry for my gibberish.

astefanutti commented 8 years ago

@carysyd I've just fixed it in fb58f1f.

That'd be great if you could give it a try to make sure that meet your needs before I cut a new release.

kriegaex commented 8 years ago

I do not know about @carysyd's needs, but the test case in my own project now runs at least:

[INFO] --- exec-maven-plugin:1.4.0:java (default-cli) @ java-app ---
#################
thisJoinPoint = execution(void de.scrum_master.app.Base.method1())
object = de.scrum_master.app.Base@6d444194
methodSignature = public void de.scrum_master.app.Base.method1()
object.timers = {public void de.scrum_master.app.Base.method1()=io.astefanutti.metrics.aspectj.AnnotatedMetric$IsPresent@538a6352}
object.timers.get(methodSignature) = io.astefanutti.metrics.aspectj.AnnotatedMetric$IsPresent@538a6352
object.timers.get(methodSignature).getMetric() = com.codahale.metrics.Timer@56e36ae4
timer = com.codahale.metrics.Timer@56e36ae4
#################
thisJoinPoint = execution(void de.scrum_master.app.Base.method1())
object = de.scrum_master.app.Derived@43a127a
methodSignature = public void de.scrum_master.app.Base.method1()
object.timers = {public void de.scrum_master.app.Base.method1()=io.astefanutti.metrics.aspectj.AnnotatedMetric$IsPresent@1ed9d82}
object.timers.get(methodSignature) = io.astefanutti.metrics.aspectj.AnnotatedMetric$IsPresent@1ed9d82
object.timers.get(methodSignature).getMetric() = com.codahale.metrics.Timer@56e36ae4
timer = com.codahale.metrics.Timer@56e36ae4
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
carysyd commented 8 years ago

Sorry guys, I'm out of town this week. I can only test it sometime in the first week of December. On Fri, Nov 27, 2015 at 2:25 PM Alexander Kriegisch < notifications@github.com> wrote:

I do not know about @carysyd https://github.com/carysyd's needs, but the test case in my own project now runs at least:

[INFO] --- exec-maven-plugin:1.4.0:java (default-cli) @ java-app --- ################# thisJoinPoint = execution(void de.scrum_master.app.Base.

method1()) object = de.scrum_master.app.Base@6d444194

methodSignature = public void de.scrum_master.app.Base.

method1() object.timers = {public void de.scrum_master.app.Base.method1()=io.astefanutti.metrics.aspectj.AnnotatedMetric$IsPresent@538a6352} object.timers.get(methodSignature) = io.astefanutti.metrics.aspectj.AnnotatedMetric$IsPresent@538a6352 object.timers.get(methodSignature).getMetric() = com.codahale.metrics.Timer@56e36ae4 timer = com.codahale.metrics.Timer@56e36ae4

################# thisJoinPoint = execution(void de.scrum_master.app.Base.

method1()) object = de.scrum_master.app.Derived@43a127a

methodSignature = public void de.scrum_master.app.Base.

method1() object.timers = {public void de.scrum_master.app.Base.method1()=io.astefanutti.metrics.aspectj.AnnotatedMetric$IsPresent@1ed9d82} object.timers.get(methodSignature) = io.astefanutti.metrics.aspectj.AnnotatedMetric$IsPresent@1ed9d82 object.timers.get(methodSignature).getMetric() = com.codahale.metrics.Timer@56e36ae4 timer = com.codahale.metrics.Timer@56e36ae4 [INFO] ------------------------------------------------------------------------ [INFO] BUILD SUCCESS [INFO] ------------------------------------------------------------------------

— Reply to this email directly or view it on GitHub https://github.com/astefanutti/metrics-aspectj/issues/11#issuecomment-160220334 .

carysyd commented 8 years ago

@astefanutti Thanks for fixing the issue. I pulled the change locally and it also passed all my tests!

astefanutti commented 8 years ago

@carysyd @kriegaex thanks for for the tests. I'll release a new version in Maven Central ASAP and let you know.

carysyd commented 8 years ago

@astefanutti Hi, Antonin. Did you get a chance to release it to Maven Central repo? Thanks.

astefanutti commented 8 years ago

@carysyd I've just released 1.1.0 version to Maven Central: http://central.maven.org/maven2/io/astefanutti/metrics/aspectj/metrics-aspectj/1.1.0/.