Guice AOP in a Fibered environment

[roded]

Hi,

I'm trying to implement a suspendable Guice MethodInterceptor and I'm encountering the following instrumentation exception:

WARNING: Uninstrumented methods (marked '**') or call-sites (marked '!!') detected on the call stack: 

at co.paralleluniverse.strands.Strand.park(java.lang.Object) (Strand.java:493)

at co.paralleluniverse.strands.ConditionSynchronizer.await(int) (ConditionSynchronizer.java:54)

at co.paralleluniverse.actors.Mailbox.await(int) (Mailbox.java:90)

at co.paralleluniverse.actors.SelectiveReceiveHelper.receive(long,java.util.concurrent.TimeUnit,co.paralleluniverse.actors.MessageProcessor) (SelectiveReceiveHelper.java:145)

at co.paralleluniverse.actors.behaviors.RequestReplyHelper.call(co.paralleluniverse.actors.ActorRef,co.paralleluniverse.actors.behaviors.RequestMessage,long,java.util.concurrent.TimeUnit) (RequestReplyHelper.java:174)

at co.paralleluniverse.actors.behaviors.RequestReplyHelper.call(co.paralleluniverse.actors.ActorRef,co.paralleluniverse.actors.behaviors.RequestMessage) (RequestReplyHelper.java:112)

at com.xxx.flow.common.GeneralActor.call(co.paralleluniverse.actors.ActorRef,co.paralleluniverse.actors.behaviors.RequestMessage) (GeneralActor.java:35) (optimized)

at com.xxx.flow.common.InRouterActor.doAct) (InRouterActor.java:107)

at com.xxx.flow.common.InRouterActor$$EnhancerByGuice$$876ef658.CGLIB$doAct$0) (<generated>) (optimized)

at com.xxx.flow.common.InRouterActor$$EnhancerByGuice$$876ef658$$FastClassByGuice$$6bcea9be.invoke(int,java.lang.Object,java.lang.Object[]) (<generated>) **

at com.google.inject.internal.cglib.proxy.$MethodProxy.invokeSuper (MethodProxy.java:228) **

at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed (InterceptorStackCallback.java:75)

at com.xxx.metrics.inject.TimerInterceptor.invoke (TimerInterceptor.java:31)

at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed (InterceptorStackCallback.java:75)

at com.google.inject.internal.InterceptorStackCallback.intercept (InterceptorStackCallback.java:55)

at com.xxx.flow.common.InRouterActor$$EnhancerByGuice$$876ef658.doAct (<generated>)

at com.xxx.flow.common.GeneralActor.doRun (GeneralActor.java:62) (optimized)

at com.xxx.flow.common.GeneralActor.doRun (GeneralActor.java:18) (optimized)

at com.xxx.flow.common.InRouterActor$$EnhancerByGuice$$876ef658.doRun (<generated>) (optimized)

at co.paralleluniverse.actors.Actor.run0 (Actor.java:691)

at co.paralleluniverse.actors.ActorRunner.run (ActorRunner.java:51)

at co.paralleluniverse.fibers.Fiber.run (Fiber.java:1027)

at co.paralleluniverse.fibers.Fiber.run1 (Fiber.java:1022)

TimerInterceptor.invoke is annotated with @Suspendable and my suspendables/suspendable-supers are respectively:

com.google.inject.internal.InterceptorStackCallback.intercept

com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed

com.google.inject.internal.cglib.proxy.$MethodProxy.invokeSuper

and:

org.aopalliance.intercept.Joinpoint.proceed

Not entirely sure what to make of the reported instrumentation issues. $MethodProxy is accounted for in suspendables and the *EnhancerByGuice classes should be extending the original class whose method throws SuspendException.

Any assistance would be great.

Thanks

[Fabio Tudone]

The verbose instrumented log ("=vdc" appended to the agent) should tell you why "com.google.inject.internal.cglib.proxy.$MethodProxy.invokeSuper" is not instrumented.

[roded]

That's a ton of data..

I copied what I thought was relevant:

[quasar] INFO: Reading class: com/google/inject/internal/cglib/proxy/$MethodProxy

[quasar] INFO: Instrumenting method com/google/inject/internal/InterceptorStackCallback$InterceptedMethodInvocation#proceed()Ljava/lang/Object;

[quasar] DEBUG: [OPTIMIZE] Examining method com/google/inject/internal/InterceptorStackCallback$InterceptedMethodInvocation#proceed()Ljava/lang/Object; with susCallsIndexes=[15, 50]

[quasar] DEBUG: Annotating method com/google/inject/internal/InterceptorStackCallback$InterceptedMethodInvocation#proceed()Ljava/lang/Object; with @Instrumented(suspendableCallSites=[75, 80],methodStart=75,methodEnd=81,methodOptimized=false)

[quasar] DEBUG: Method call at instruction 15 to com/google/inject/internal/cglib/proxy/$MethodProxy#invokeSuper(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object; is suspendable

[quasar] DEBUG: Splitting try-catch in proceed, block 0 call at instruction 15

[quasar] DEBUG: Splitting try-catch in proceed, block 1 call at instruction 15

[quasar] DEBUG: Method call at instruction 38 to com/google/inject/internal/InterceptorStackCallback$InterceptedMethodInvocation#<init>(Lcom/google/inject/internal/InterceptorStackCallback;Ljava/lang/Object;Lcom/google/inject/internal/cglib/proxy/$MethodProxy;[Ljava/lang/Object;I)V is not suspendable

[quasar] DEBUG: Method call at instruction 39 to org/aopalliance/intercept/MethodInterceptor#invoke(Lorg/aopalliance/intercept/MethodInvocation;)Ljava/lang/Object; is not suspendable

[quasar] DEBUG: Synthetic accessor method call at instruction 50 is assumed suspendable

...

[quasar] INFO: Method com/google/inject/internal/cglib/proxy/$MethodProxy#invokeSuper suspendable: SUSPENDABLE (markedSuspendable: SUSPENDABLE setSuspendable: SUSPENDABLE)

[quasar] INFO: About to instrument method com/google/inject/internal/cglib/proxy/$MethodProxy#invokeSuper(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;

[quasar] INFO: Reading class: java/lang/reflect/InvocationTargetException

[quasar] INFO: Reading class: java/lang/ReflectiveOperationException

[quasar] INFO: Nothing to instrument in method com/google/inject/internal/cglib/proxy/$MethodProxy#invokeSuper(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;

[roded]

The method looks something like this:

public Object invokeSuper(Object obj, Object[] args)

    throws Throwable

  {

    try

    {

      init();

      FastClassInfo fci = this.fastClassInfo;

      return fci.f2.invoke(fci.i2, obj, args);

    }

    catch (InvocationTargetException e)

    {

      throw e.getTargetException();

    }

  }

I added the following to suspendable-supers:

com.google.inject.internal.cglib.reflect.$FastClass.invoke

Now, $MethodProxy.invokeSuper is not marked as uninstrumented, but the EnhancerByGuice method right after it it marked as such.

[Fabio Tudone]

Yes, it looks like Guice uses a relocated CGLIB. You're on the right track, you've found the call site type and instrumented the caller. The log should also tell you about the reason why the "EnhancerByGuice" method is uninstrumented but since FastClass is abstract I guess a subclass that implements "invoke" is dynamically generated. What happens if you add the "EnhancerByGuice" invoke method to "suspendables"?

[roded]

That class name seems random, does suspendables accept wildcards? :)

As for the log, this is the relevant line it seems:

[quasar] INFO: Method com/modelity/marketplace/flow/common/InRouterActor$$EnhancerByGuice$$54939878$$FastClassByGuice$$97c1f716#invoke suspendable: NON_SUSPENDABLE (markedSuspendable: NON_SUSPENDABLE setSuspendable: null)

[Fabio Tudone]

So you've told the instrumentor that call sites towards the abstract "$FastClass.invoke" methods could end up calling suspendable concrete overrides and the instrumentor now says OK but it doesn't know that "com/modelity/marketplace/flow/common/InRouterActor$$EnhancerByGuice$$54939878$$FastClassByGuice$$97c1f716#invoke" is indeed one such suspendable concrete override and so is not instrumenting it. So basically you have to tell it that it is a suspendable concrete override and must be examined for instrumentation.

Quasar uses a plugin system to find information about suspendable concrete methods (type "SUSPENDABLE") and abstract methods whose overrides could be SUSPENDABLE (i.e. type "SUSPENDABLE_SUPER"). The plugin system is based on ServiceLoader, the service interface is SuspendableClassifier (which has only one "isSuspendable" method returning a MethodDatabase.SuspendableType enum value or "null" if it doesn't want to say anything about a method) and the available implementations (listed in all loadable "META-INF/services" resources) are all consulted here in DefaultSuspendableClassifier (which is, too, a "SuspendableClassifier").

Actually, the "META-INF/suspendables" and "META-INF/suspendable-supers" are processed by one such service implementation, SimpleSuspendableClassifier, which supports reading from those files full method names in "dot" notation, one per line, with or without type descriptor, as well as a wildcard for methods but not for classes.

I'm not familiar with CGLIB's inners but I think the name is not fully random, rather based on a hash of some notion of identity about the method being proxied: it should not change depending on the run and maybe not even if the proxied method implementation changes, possibly only based on the name and signature. You can try few changes and see.

Anyway, you could just add it temporarily to "suspendables" to see if that is indeed what's missing. Then, a more robust and general strategy would be writing your own SuspendableClassifier implementation (and "META-INF/services" resource) whose "isSuspendable" will return "SUSPENDABLE" if the method name matches some heuristic (e.g. if it contains "$$Enhancer" and "$$FastClass").

-- Fabio

[Fabio Tudone]

Quasar uses a plugin system to find information about suspendable

 

(That is, in addition to javac-checked "throws SuspendExecution" and (unchecked) "@Suspendable" annotations).

[roded]

That is truly very cool.

Thanks for the explanation.

I've implemented the classifier and it seems to be active.

However, I now get the following errors on application load:

[quasar] WARNING: Expected to find a NewValue on stack index 1: Lcom/xxx/flow/common/InRouterActor$$EnhancerByGuice$$614a6ff0$$FastClassByGuice$$5aefc57f;ILjava/lang/Object;[Ljava/lang/Object; Ljava/lang/Boolean;Ljava/lang/Boolean;I

[quasar] WARNING: Expected to find a NewValue on stack index 1: Lcom/xxx/flow/common/InRouterActor$$EnhancerByGuice$$614a6ff0$$FastClassByGuice$$5aefc57f;ILjava/lang/Object;[Ljava/lang/Object; Ljava/lang/Integer;Ljava/lang/Integer;I

[quasar] WARNING: Expected to find a NewValue on stack index 1: Lcom/xxx/flow/common/InRouterActor$$EnhancerByGuice$$614a6ff0$$FastClassByGuice$$5aefc57f;ILjava/lang/Object;[Ljava/lang/Object; Ljava/lang/Boolean;Ljava/lang/Boolean;I

[quasar] WARNING: Expected to find a NewValue on stack index 1: Lcom/xxx/flow/common/InRouterActor$$EnhancerByGuice$$614a6ff0$$FastClassByGuice$$5aefc57f;ILjava/lang/Object;[Ljava/lang/Object; Ljava/lang/Boolean;Ljava/lang/Boolean;I

[quasar] WARNING: Expected to find a NewValue on stack index 1: Lcom/xxx/flow/common/InRouterActor$$EnhancerByGuice$$614a6ff0$$FastClassByGuice$$5aefc57f;ILjava/lang/Object;[Ljava/lang/Object; Ljava/lang/Boolean;Ljava/lang/Boolean;I

[quasar] WARNING: Expected to find a NewValue on stack index 1: Lcom/xxx/flow/common/InRouterActor$$EnhancerByGuice$$614a6ff0$$FastClassByGuice$$5aefc57f;ILjava/lang/Object;[Ljava/lang/Object; Ljava/lang/Boolean;Ljava/lang/Boolean;I

[quasar] WARNING: Expected to find a NewValue on stack index 1: Lcom/xxx/flow/common/InRouterActor$$EnhancerByGuice$$614a6ff0$$FastClassByGuice$$5aefc57f;ILjava/lang/Object;[Ljava/lang/Object; Ljava/lang/Integer;Ljava/lang/Integer;I

[quasar] WARNING: Expected to find a NewValue on stack index 1: Lcom/xxx/flow/common/InRouterActor$$EnhancerByGuice$$614a6ff0$$FastClassByGuice$$5aefc57f;ILjava/lang/Object;[Ljava/lang/Object; Ljava/lang/reflect/InvocationTargetException;Ljava/lang/reflect/InvocationTargetException;Ljava/lang/Throwable;

But more importantly, even though the un-instrumentation mark (**) is now gone, the symptom of the issue remains exactly the same:

Exception in Fiber "fiber-10000007" If this exception looks strange, perhaps you've forgotten to instrument a blocking method. Run your program with -Dco.paralleluniverse.fibers.verifyInstrumentation to catch the culprit!

java.lang.NullPointerException

at co.paralleluniverse.strands.Strand.park(Strand.java:493)

at co.paralleluniverse.strands.ConditionSynchronizer.await(ConditionSynchronizer.java:54)

at co.paralleluniverse.actors.Mailbox.await(Mailbox.java:90)

at co.paralleluniverse.actors.SelectiveReceiveHelper.receive(SelectiveReceiveHelper.java:145)

at co.paralleluniverse.actors.behaviors.RequestReplyHelper.call(RequestReplyHelper.java:174)

at co.paralleluniverse.actors.behaviors.RequestReplyHelper.call(RequestReplyHelper.java:112)

at com.xxx.flow.common.GeneralActor.call(GeneralActor.java:35)

at com.xxx.flow.common.InRouterActor.doAct(InRouterActor.java:107)

at com.xxx.flow.common.InRouterActor$$EnhancerByGuice$$ad937cc0.CGLIB$doAct$0(<generated>)

at com.xxx.flow.common.InRouterActor$$EnhancerByGuice$$ad937cc0$$FastClassByGuice$$5da08793.invoke(<generated>)

at com.google.inject.internal.cglib.proxy.$MethodProxy.invokeSuper(MethodProxy.java:228)

at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:75)

at com.xxx.metrics.inject.TimerInterceptor.invoke(TimerInterceptor.java:31)

at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:75)

at com.google.inject.internal.InterceptorStackCallback.intercept(InterceptorStackCallback.java:55)

at com.xxx.flow.common.InRouterActor$$EnhancerByGuice$$ad937cc0.doAct(<generated>)

at com.xxx.flow.common.GeneralActor.doRun(GeneralActor.java:62)

at com.xxx.flow.common.GeneralActor.doRun(GeneralActor.java:18)

at com.xxx.flow.common.InRouterActor$$EnhancerByGuice$$ad937cc0.doRun(<generated>)

at co.paralleluniverse.actors.Actor.run0(Actor.java:691)

at co.paralleluniverse.actors.ActorRunner.run(ActorRunner.java:51)

at co.paralleluniverse.fibers.Fiber.run(Fiber.java:1027)

Any idea what could cause this?

Thanks

[Fabio Tudone]

Which Quasar version are you using? Is instrumentation verification still enabled and are you sure there aren't other verification messages?

You can ignore the warning, it is about a bytecode pattern for object construction and initialization when suspendable call results are passed as parameters to a constructor; that pattern can be different from usual in dynamically generated code (like CGLIBs). One thing this could mean though is that your heuristic is declaring a lot of methods as suspendable even if it's not needed, I think you should restrict your Classifier heuristic to catch only the cases that interest you.

-- Fabio

[roded]

0.7.5.

Yeah, there are no other verification messages.. I suspected the same myself and set verifyInstrumentation to true hardcoded.

The current classifier test is:

if (className.contains("$$EnhancerByGuice")
    && className.contains("$$FastClassByGuice$$")
    && methodName.equals("invoke")) {
  return MethodDatabase.SuspendableType.SUSPENDABLE;
}

[Fabio Tudone]

OK, you could try Quasar 0.7.6-SNAPSHOT as verification has been recently updated.

If it doesn't work then possibly there's a bug in the verification that makes it miss some uninstrumented methods and/or call sites; it could be related to this issue and anyway the circumstance seems to be the one described in this comment so in the meanwhile you could try verifying manually starting from the top of the stack trace as described there.

If you open an issue or follow up on the existing one, a small self-contained example that reproduces it (project or set of gists, including build file) would be very helpful.

-- Fabio

[roded]

https://github.com/roded/quasar-guice

Up till the introduction of the classifier, the behaviour was as expected (that is, just like in my main project).

After adding the classifier though, no exceptions are thrown in case of this project, but rather, there seems to be something odd going on with the method calls.

Instead of the expected:

before invocation

before sleep

after sleep

after invocation

I'm getting:

before invocation

before sleep

before invocation

before sleep

after sleep

after invocation

[roded]

Same with 0.7.6-SNAPSHOT btw

[Fabio Tudone]

At present there's one important limitation of instrumentation verification that I hadn't thought about earlier: if two or more suspendable calls are on the same source line and at least one of them is instrumented and at least one is uninstrumented, the verification can't detect the uninstrumented ones (because it relies on source lines to identify suspendable call sites, because at present there's no BCI information in stack traces).

If there's no source line information in the bytecode (as it happens with synthetic methods) then all source lines will be "-1", which means that verification can spot uninstrumented methods but not uninstrumented call sites (if at least one of them has been instrumented in the method, that is): this makes instrumenting CGLIB-generated code more challenging because verification needs to be done manually by looking for something uninstrumented in the instrumentor logs, following the suspending stack trace top-to-bottom (f.e. you can print one before "sleep" with "new Throwable().printStackTrace()"). The unavailability of the source also means that the "javap -v -p" against the generated classes is the only available reference to see what's actually executing (have a look here) or, as an indirect alternative, CGLIB's sources that generate the relevant bytecode.

-- Fabio

[roded]

I reduced the stack a bit by sleeping in the Interceptor itself:

java.lang.Throwable

at test.test.Interceptor.invoke(Interceptor.java:20)

at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:75)

at com.google.inject.internal.InterceptorStackCallback.intercept(InterceptorStackCallback.java:55)

at test.test.TestActor$$EnhancerByGuice$$febeab15.test(<generated>)

at test.test.TestActor.doRun(TestActor.java:14)

at co.paralleluniverse.actors.Actor.run0(Actor.java:691)

at co.paralleluniverse.actors.ActorRunner.run(ActorRunner.java:51)

at co.paralleluniverse.fibers.Fiber.run(Fiber.java:1027)

at co.paralleluniverse.fibers.Fiber.run1(Fiber.java:1022)

at co.paralleluniverse.fibers.Fiber.exec(Fiber.java:732)

at co.paralleluniverse.fibers.FiberForkJoinScheduler$FiberForkJoinTask.exec1(FiberForkJoinScheduler.java:265)

at co.paralleluniverse.concurrent.forkjoin.ParkableForkJoinTask.doExec(ParkableForkJoinTask.java:117)

at co.paralleluniverse.concurrent.forkjoin.ParkableForkJoinTask.exec(ParkableForkJoinTask.java:74)

at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)

at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)

at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)

at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)

In this case, the unexpected output is:

before invocation

before invocation

after invocation

There are instances of calls where, as you mentioned, two such calls are on the same line such as in InterceptorStackCallback.intercept() and.InterceptorStackCallback$InterceptedMethodInvocation.proceed.

Here's what the log says about each method post the TestActor.doRun():

 test.test.TestActor$$EnhancerByGuice$$febeab15.test(<generated>):

        Line 5998: [quasar] INFO: Method test/test/TestActor$$EnhancerByGuice$$febeab15#test suspendable: SUSPENDABLE (markedSuspendable: SUSPENDABLE setSuspendable: null)

Line 6011: [quasar] INFO: About to instrument method test/test/TestActor$$EnhancerByGuice$$febeab15#test()V

Line 6012: [quasar] INFO: Instrumenting method test/test/TestActor$$EnhancerByGuice$$febeab15#test()V

Line 6013: [quasar] DEBUG: [OPTIMIZE] Examining method test/test/TestActor$$EnhancerByGuice$$febeab15#test()V with susCallsIndexes=[20]

Line 6014: [quasar] DEBUG: Annotating method test/test/TestActor$$EnhancerByGuice$$febeab15#test()V with @Instrumented(suspendableCallSites=[-1],methodStart=-1,methodEnd=-1,methodOptimized=false)

Line 6123: [quasar] DEBUG: Method call at instruction 6 to test/test/TestActor$$EnhancerByGuice$$febeab15#test()V is suspendable

com.google.inject.internal.InterceptorStackCallback.intercept(InterceptorStackCallback.java:55):

        Line 5743: [quasar] INFO: Method com/google/inject/internal/InterceptorStackCallback#intercept suspendable: SUSPENDABLE (markedSuspendable: SUSPENDABLE setSuspendable: null)

       Line 5747: [quasar] INFO: About to instrument method com/google/inject/internal/InterceptorStackCallback#intercept(Ljava/lang/Object;Ljava/lang/reflect/Method;[Ljava/lang/Object;Lcom/google/inject/internal/cglib/proxy/$MethodProxy;)Ljava/lang/Object;

       Line 5752: [quasar] INFO: Instrumenting method com/google/inject/internal/InterceptorStackCallback#intercept(Ljava/lang/Object;Ljava/lang/reflect/Method;[Ljava/lang/Object;Lcom/google/inject/internal/cglib/proxy/$MethodProxy;)Ljava/lang/Object;

       Line 5753: [quasar] DEBUG: [OPTIMIZE] Examining method com/google/inject/internal/InterceptorStackCallback#intercept(Ljava/lang/Object;Ljava/lang/reflect/Method;[Ljava/lang/Object;Lcom/google/inject/internal/cglib/proxy/$MethodProxy;)Ljava/lang/Object; with susCallsIndexes=[10]

       Line 5754: [quasar] DEBUG: Annotating method com/google/inject/internal/InterceptorStackCallback#intercept(Ljava/lang/Object;Ljava/lang/reflect/Method;[Ljava/lang/Object;Lcom/google/inject/internal/cglib/proxy/$MethodProxy;)Ljava/lang/Object; with @Instrumented(suspendableCallSites=[55],methodStart=55,methodEnd=55,methodOptimized=false)

com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:75):

       Line 5756: [quasar] DEBUG: Method call at instruction 10 to com/google/inject/internal/InterceptorStackCallback$InterceptedMethodInvocation#proceed()Ljava/lang/Object; is suspendable

      Line 5761: [quasar] INFO: Method com/google/inject/internal/InterceptorStackCallback$InterceptedMethodInvocation#proceed suspendable: SUSPENDABLE (markedSuspendable: SUSPENDABLE setSuspendable: SUSPENDABLE)

      Line 5766: [quasar] INFO: About to instrument method com/google/inject/internal/InterceptorStackCallback$InterceptedMethodInvocation#proceed()Ljava/lang/Object;

      Line 5768: [quasar] INFO: Instrumenting method com/google/inject/internal/InterceptorStackCallback$InterceptedMethodInvocation#proceed()Ljava/lang/Object;

      Line 5769: [quasar] DEBUG: [OPTIMIZE] Examining method com/google/inject/internal/InterceptorStackCallback$InterceptedMethodInvocation#proceed()Ljava/lang/Object; with susCallsIndexes=[15, 39, 50]

      Line 5770: [quasar] DEBUG: Annotating method com/google/inject/internal/InterceptorStackCallback$InterceptedMethodInvocation#proceed()Ljava/lang/Object; with @Instrumented(suspendableCallSites=[75, 75, 80],methodStart=75,methodEnd=81,methodOptimized=false)

test.test.Interceptor.invoke(Interceptor.java:20)

   Line 3458: [quasar] INFO: Method org/aopalliance/intercept/MethodInterceptor#invoke suspendable: SUSPENDABLE_SUPER (markedSuspendable: SUSPENDABLE_SUPER setSuspendable: null)

  Line 3463: [quasar] INFO: Method test/test/Interceptor#invoke suspendable: SUSPENDABLE (markedSuspendable: SUSPENDABLE setSuspendable: null)

  Line 3464: [quasar] INFO: About to instrument method test/test/Interceptor#invoke(Lorg/aopalliance/intercept/MethodInvocation;)Ljava/lang/Object;

  Line 3465: [quasar] INFO: Instrumenting method test/test/Interceptor#invoke(Lorg/aopalliance/intercept/MethodInvocation;)Ljava/lang/Object;

  Line 3466: [quasar] DEBUG: [OPTIMIZE] Examining method test/test/Interceptor#invoke(Lorg/aopalliance/intercept/MethodInvocation;)Ljava/lang/Object; with susCallsIndexes=[14]

  Line 3467: [quasar] DEBUG: Annotating method test/test/Interceptor#invoke(Lorg/aopalliance/intercept/MethodInvocation;)Ljava/lang/Object; with @Instrumented(suspendableCallSites=[21],methodStart=19,methodEnd=24,methodOptimized=false)

  Line 5775: [quasar] DEBUG: Method call at instruction 39 to org/aopalliance/intercept/MethodInterceptor#invoke(Lorg/aopalliance/intercept/MethodInvocation;)Ljava/lang/Object; to suspendable-super (instrumentation for proxy support will be enabled)

       

As for the bytecode, it looks fine to my untrained eye (i.e., these methods look instrumented).

test.test.TestActor$$EnhancerByGuice$$febeab15.test() does not seem to be doing anything special and the invokeinterface seems instrumented properly.

Any idea what I'm missing?

[roded]

Was missing the banal org.aopalliance.intercept.MethodInterceptor.invoke as it turns out.

Thanks for the assistance.

On Monday, May 16, 2016 at 3:34:00 PM UTC+3, roded wrote:

[Fabio Tudone]

Ah I see, good catch! In which trace (or how else) did you find that out?

As an aside: there might be something we can try to improve even pre-Java 9 when verifying call sites in stack frames without source lines. We'll need to think about it some more though.

-- Fabio

[roded]

The agent log + your recommendation regarding printing the stacktrace at the problematic site was most helpfulww.

I just missed the most obvious method two days ago.  

In this case, there was no instrumentation error.. just a popMethod to the wrong place I guess.

[Fabio Tudone]

It too seems to be caused by the current verification limit we've discussed. This is the relevant instrumentation log portion (the call to "invoke" should be SUSPENDABLE_SUPER):

[quasar] INFO: Instrumenting method com/google/inject/internal/InterceptorStackCallback$InterceptedMethodInvocation#proceed()Ljava/lang/Object;

...

[quasar] DEBUG: Annotating method com/google/inject/internal/InterceptorStackCallback$InterceptedMethodInvocation#proceed()Ljava/lang/Object; with @Instrumented(suspendableCallSites=[75, 80],methodStart=75,methodEnd=81,methodOptimized=false)
[quasar] DEBUG: Method call at instruction 15 to com/google/inject/internal/cglib/proxy/$MethodProxy#invokeSuper(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object; is suspendable

...
[quasar] DEBUG: Method call at instruction 39 to org/aopalliance/intercept/MethodInterceptor#invoke(Lorg/aopalliance/intercept/MethodInvocation;)Ljava/lang/Object; is not suspendable

So "invokeSuper" is SUSPENDABLE (-> instrumented call site) but "invoke" is not "SUSPENDABLE_SUPER" (-> call site not instrumented even though it should be). The code is as follows:

    public Object proceed() throws Throwable {
      try {
        return index == interceptors.length
            ? methodProxy.invokeSuper(proxy, arguments)
            : interceptors[index].invoke(
                new InterceptedMethodInvocation(proxy, methodProxy, arguments, index + 1));
      } catch (Throwable t) {
        pruneStacktrace(t);
        throw t;
      }
    }

The corresponding invocation bytecode lines from "javap -p -v" are:

        27: invokevirtual #51                 // Method com/google/inject/internal/cglib/proxy/$MethodProxy.invokeSuper:(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;

        ...

        74: invokeinterface #59,  2           // InterfaceMethod org/aopalliance/intercept/MethodInterceptor.invoke:(Lorg/aopalliance/intercept/MethodInvocation;)Ljava/lang/Object;

And the source lines table is:

      LineNumberTable:
        line 75: 0
        line 79: 80
        line 80: 81
        line 81: 89

This means that from the start of the method (byte offset 0) until byte offset 78 incl. the source line is 75. This byte offset interval includes both call sites (27 and 74) so we're in the situation where some call sites are instrumented and some not in the same source line.

It should be a rare occurrence but after all there seem to be some cases, like AoP or maybe generally invocation-level tools, where it's not so rare. Could open a GitHub feature request about improving detection in these situations?

Thanks,

-- Fabio

[roded]

That's really elucidating. Thanks.

Sure: https://github.com/puniverse/quasar/issues/193

I quoted you there, hope that's OK.

Also, is there currently a way to hide those "Expected to find a NewValue on stack index 1" warnings? I'm getting a warning per proxied method which is going to be quite a bit.

[Fabio Tudone]

Thanks. At the present there isn't but it's logged on stderr at class instrumentation (loading) time so it shouldn't really bother too much. Or does it?

[roded]

It's about 100 warnings which are printed to the console when the application is started locally.

Nothing serious, though if the warnings' cause is here to stay, it would be nice to be able to ignore them.