guice+profiler4j = Inconsistent stack height 1 != 2

[Andreas]

hi!

i tried profiling my app, but it turns out there are some impediments
which make profiler4j not work with guice.
i as soon as i fire up an injector while under the -
javaagent:agent.jar i get the following stacktrace:
anyone experienced something similar? has anyone used a profiler
successfully with guice?

16.03.2009 01:16:52 org.apache.catalina.core.StandardContext
listenerStart
SCHWERWIEGEND: Error configuring application listener of class
quan.bindings.Init
java.lang.AssertionError: java.lang.AssertionError:
java.lang.VerifyError: (class: quan/data/dao/LanguageDao$
$EnhancerByGuice$$3f29a8d5, method: makeTransient signature: (Ljava/
lang/Object;)V) Inconsistent stack height 1 != 2
at com.google.inject.InjectorImpl.getImplicitBinding
(InjectorImpl.java:984)
at com.google.inject.InjectorImpl.getInternalFactory
(InjectorImpl.java:308)
at com.google.inject.BindingBuilderImpl$FactoryProxy$1.run
(BindingBuilderImpl.java:293)
at com.google.inject.InjectorImpl.withDefaultSource(InjectorImpl.java:
142)
at com.google.inject.BindingBuilderImpl$FactoryProxy.notify
(BindingBuilderImpl.java:291)
at com.google.inject.BinderImpl.createInjector(BinderImpl.java:264)
at com.google.inject.Guice.createInjector(Guice.java:79)
at com.google.inject.Guice.createInjector(Guice.java:53)
at com.google.inject.Guice.createInjector(Guice.java:43)
at quan.bindings.Init.buildInjector(Init.java:52)
at quan.bindings.Init.<init>(Init.java:39)
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native
Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance
(NativeConstructorAccessorImpl.java:39)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance
(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at java.lang.Class.newInstance0(Class.java:355)
at java.lang.Class.newInstance(Class.java:308)
at org.apache.catalina.core.StandardContext.listenerStart
(StandardContext.java:3787)
at org.apache.catalina.core.StandardContext.start
(StandardContext.java:4342)
at org.apache.catalina.core.ContainerBase.addChildInternal
(ContainerBase.java:791)
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:
771)
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:
525)
at org.apache.catalina.startup.HostConfig.deployDescriptor
(HostConfig.java:627)
at org.apache.catalina.startup.HostConfig.deployDescriptors
(HostConfig.java:553)
at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:
488)
at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1149)
at org.apache.catalina.startup.HostConfig.lifecycleEvent
(HostConfig.java:311)
at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent
(LifecycleSupport.java:117)
at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:
1053)
at org.apache.catalina.core.StandardHost.start(StandardHost.java:719)
at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:
1045)
at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:
443)
at org.apache.catalina.core.StandardService.start
(StandardService.java:516)
at org.apache.catalina.core.StandardServer.start(StandardServer.java:
710)
at org.apache.catalina.startup.Catalina.start(Catalina.java:578)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke
(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke
(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413)
Caused by: java.lang.AssertionError: java.lang.VerifyError: (class:
quan/data/dao/LanguageDao$$EnhancerByGuice$$3f29a8d5, method:
makeTransient signature: (Ljava/lang/Object;)V) Inconsistent stack
height 1 != 2
at com.google.inject.InjectorImpl.getImplicitBinding
(InjectorImpl.java:984)
at com.google.inject.InjectorImpl.getInternalFactory
(InjectorImpl.java:300)
at com.google.inject.InjectorImpl.createParameterInjector
(InjectorImpl.java:524)
at com.google.inject.InjectorImpl.getParametersInjectors
(InjectorImpl.java:515)
at com.google.inject.ConstructorInjector.createParameterInjector
(ConstructorInjector.java:57)
at com.google.inject.ConstructorInjector.<init>
(ConstructorInjector.java:38)
at com.google.inject.InjectorImpl$7.create(InjectorImpl.java:601)
at com.google.inject.InjectorImpl$7.create(InjectorImpl.java:594)
at com.google.inject.util.ReferenceCache.create(ReferenceCache.java:
53)
at com.google.inject.util.AbstractReferenceCache.internalCreate
(AbstractReferenceCache.java:59)
at com.google.inject.util.AbstractReferenceCache.get
(AbstractReferenceCache.java:116)
at com.google.inject.InjectorImpl.getConstructor(InjectorImpl.java:
765)
at com.google.inject.InjectorImpl.getImplicitBinding
(InjectorImpl.java:973)
... 40 more
Caused by: java.lang.VerifyError: (class: quan/data/dao/LanguageDao$
$EnhancerByGuice$$3f29a8d5, method: makeTransient signature: (Ljava/
lang/Object;)V) Inconsistent stack height 1 != 2
at java.lang.Class.getDeclaredMethods0(Native Method)
at java.lang.Class.privateGetDeclaredMethods(Class.java:2427)
at java.lang.Class.getDeclaredMethod(Class.java:1935)
at com.google.inject.cglib.proxy.Enhancer.getCallbacksSetter
(Enhancer.java:627)
at com.google.inject.cglib.proxy.Enhancer.setCallbacksHelper
(Enhancer.java:615)
at com.google.inject.cglib.proxy.Enhancer.registerStaticCallbacks
(Enhancer.java:591)
at com.google.inject.ProxyFactory.createConstructionProxy
(ProxyFactory.java:158)
at com.google.inject.ProxyFactory$1.create(ProxyFactory.java:57)
at com.google.inject.ProxyFactory$1.create(ProxyFactory.java:56)
at com.google.inject.util.ReferenceCache.create(ReferenceCache.java:
53)
at com.google.inject.util.AbstractReferenceCache.internalCreate
(AbstractReferenceCache.java:59)
at com.google.inject.util.AbstractReferenceCache.get
(AbstractReferenceCache.java:116)
at com.google.inject.ProxyFactory.get(ProxyFactory.java:204)
at com.google.inject.ConstructorInjector.<init>
(ConstructorInjector.java:41)
at com.google.inject.InjectorImpl$7.create(InjectorImpl.java:601)
at com.google.inject.InjectorImpl$7.create(InjectorImpl.java:594)
at com.google.inject.util.ReferenceCache.create(ReferenceCache.java:
53)
at com.google.inject.util.AbstractReferenceCache.internalCreate
(AbstractReferenceCache.java:59)
at com.google.inject.util.AbstractReferenceCache.get
(AbstractReferenceCache.java:116)
at com.google.inject.InjectorImpl.getConstructor(InjectorImpl.java:
765)
at com.google.inject.InjectorImpl.getImplicitBinding
(InjectorImpl.java:973)
... 52 more

[Stuart McCulloch]

2009/3/16 Andreas <and...@petersson.at>

hi!

i tried profiling my app, but it turns out there are some impediments
which make profiler4j not work with guice.
i as soon as i fire up an injector while under the -
javaagent:agent.jar i get the following stacktrace:
anyone experienced something similar? has anyone used a profiler
successfully with guice?

I haven't used Profiler4j myself, but the exception suggests that it tried to
use bytecode modification on a CGLIB generated class created by Guice

Profiler4j might be expecting a very specific bytecode structure (possibly
like the type javac produces) so while the CGLIB proxy class is originally
valid bytecode (although different to javac's) the profiled bytecode is not
because of assumptions made by Profiler4j

have you tried turning off profiling of these CGLIB generated classes?

ie. looking briefly at the Profiler4j docs this would be something like:

   *ByGuice*(*)        REJECT

note this rule should appear early in the list, before any accept rules

HTH

--
Cheers, Stuart

[Endre Stølsvik]

Hi!

This is just me wondering out loud, hoping for a cluestick:

Haven't there been slightly more than a few of these inconsistent
stack heights problems, with various tools? I've never heard of that
error before Guice, and now I feel I've seen them several times.
Here's two more than this third:
http://code.google.com/p/google-guice/issues/detail?id=168
http://forum.limewire.org/showthread.php?t=3602

Where is this stack depth measurement done? I don't understand how it
is possible to get such inconsistencies given correct behavior from
all parts (although I got to admit that this is way out on the fringe
of my knowledge): If one set of bytecode transformations or
productions is legal and consistent, and another set also is legal and
consistent, how is it possible that the combination of those two
aren't? I could see something like, figuratively, trying to make some
HTML text bold and then italic using two distinct transformations, and
ending up with <b><i>BoldItalic</b></i>. But if something remotely
like that is happening, then one of those tools is doing something
illegal, right?

.. and doesn't this potentially point to some rather obscure, and
possibly slightly illegal stuff, done by CGLib, or is it always the
other tool getting it wrong (which now then includes at least TPTP,
profiler4j, and some "performance monitoring & profiling tool from
HP")? The tool that last touches the code is the prime suspect, right?
Is that CGLib or the other tool?

Endre.

[Stuart McCulloch]

2009/3/16 Endre Stølsvik <stol...@gmail.com>

Hi!

This is just me wondering out loud, hoping for a cluestick:

Haven't there been slightly more than a few of these inconsistent
stack heights problems, with various tools? I've never heard of that
error before Guice, and now I feel I've seen them several times.
Here's two more than this third:
 http://code.google.com/p/google-guice/issues/detail?id=168
 http://forum.limewire.org/showthread.php?t=3602

actually this isn't limited to Guice, it seems to be more related to profiling,
especially of CGLIB generated bytecode which while valid, is "unusual":

  http://forum.springframework.org/showthread.php?t=51455
  https://bugs.eclipse.org/bugs/show_bug.cgi?id=117854

another factor is that more people are using Java6 which I believe does
more bytecode verification (certainly the 1.6 javac generates additional
information about the operand stack to speed up bytecode verification)
 

Where is this stack depth measurement done?

it is part of bytecode verification, which is done by the JVM when you
load a class to make sure that all potential paths have a consistent
height (ie. so you don't pop too much off, or leave anything hanging
around, etc.)

   http://java.sun.com/docs/white/langenv/Security.doc3.html

also note you can turn off bytecode verification with "-Xverify:none"
 

I don't understand how it
is possible to get such inconsistencies given correct behavior from
all parts (although I got to admit that this is way out on the fringe
of my knowledge): If one set of bytecode transformations or
productions is legal and consistent, and another set also is legal and
consistent, how is it possible that the combination of those two
aren't?

it can happen if one transformation assumes a certain "shape" of bytecode

for example say I write a profiler that inserts instructions at the start and
end of a method - if I look at javac generated bytecode it always follows a
straightforward pattern ( that's why you can easily de-compile it :) so I can
tell where the method entry and exit points are

but handcrafted or "non-javac" bytecode doesn't have to fit this pattern,
and is way more flexible than the Java language itself (see all the scripted
languages that can compile down to bytecode) and might have exit points
scattered throughout the bytecode

in such situations you have to be _very_ careful how you transform it

[ quick word about optimization of bytecode - some JIT compilers look for
  certain patterns in the code where they can apply specific optimizations,
  so if you optimize your bytecode away from the "javac" pattern you may
  find it actually decreases your JIT'd code performance! ]

I could see something like, figuratively, trying to make some
HTML text bold and then italic using two distinct transformations, and
ending up with <b><i>BoldItalic</b></i>. But if something remotely
like that is happening, then one of those tools is doing something
illegal, right?

correct

.. and doesn't this potentially point to some rather obscure, and
possibly slightly illegal stuff, done by CGLib, or is it always the
other tool getting it wrong (which now then includes at least TPTP,
profiler4j, and some "performance monitoring & profiling tool from
HP")? The tool that last touches the code is the prime suspect, right?
Is that CGLib or the other tool?

the last thing to touch the code in this case is the profiling tool which
attaches itself as a JVMTI agent - it is intercepting the byte array that
CGLIB creates and transforms it to add profiling hooks before passing
it onto the JVM to load as normal

if CGLIB was generating invalid bytecode then I would expect to see
the verify error when you didn't use a profiler - so far I've only seen
this when profilers are involved...

--
Cheers, Stuart

[Endre Stølsvik]

Hi!

Thanks for a very informative answer!

>
> if CGLIB was generating invalid bytecode then I would expect to see
> the verify error when you didn't use a profiler - so far I've only seen
> this when profilers are involved...

Well, the idea was that only when it came "last" to the code,
transformations it yielded could end up wrong. Thus you would never
observe an error with this as the sole tool. Also, one of the tools
could be more robust than the other, so that it consistently handled
being last, while the other didn't tackle that. Just musings..

I think that CGLib should fix that "unusualness" of itself (apparently
the number of explicit pops it sticks in before the multiple return
points it generates?!), adhering to Postel's law: Be conservative in
what you do; be liberal in what you accept from others. At least, it
could have some switch that could produce conservative code (default),
or drop this for the last bit of performance. And obviously, it might
well be that it really is the other tools that are in error - but that
isn't very helpful.

Endre.

[Yegor]

Aren't all profiling tools using the same Java Virtual Machine
Profiling Interface? If so, we only have one CGLIB against one JVMPI,
_not_ one CGLIB against many profiling tools. Profiling tools are
merely front-ends that exchange events with JVMPI. So either CGLIB or
JVMPI (or both) could be responsible for the error.

Anyway, I'll have to agree with Stuart. Profiling dynamically
generated byte-code may not give you reliable numbers. It is better to
exclude generated classes from instrumentation target list and instead
measure the performance of classes that call generated code. Note that
I am only talking about CPU profiling. Memory is a different issue.
Have you tried different profiling modes (memory, CPU, code coverage)?
Are all of them failing?

Yegor

[Stuart McCulloch]

2009/3/17 Yegor <Yegor....@gmail.com>

Aren't all profiling tools using the same Java Virtual Machine
Profiling Interface? If so, we only have one CGLIB against one JVMPI,
_not_ one CGLIB against many profiling tools. Profiling tools are
merely front-ends that exchange events with JVMPI. So either CGLIB or
JVMPI (or both) could be responsible for the error.

modern profilers tend to use the JVMTI hooks that were introduced in Java 5
rather than the experimental, deprecated* JVMPI hooks (* Sun's own words!)

   http://java.sun.com/developer/technicalArticles/Programming/jvmpitransition/

one of these hooks is the ability to redefine bytecode as it's loaded to mix
in snippets of profiling bytecode - this appears to be what Profiler4j uses

unfortunately while this gives the profiling agent great power it also brings
great responsibility ;) because it's not using a standard set of entry / exit
hooks added by the JVM, but is transforming bytecode using its own rules.

Anyway, I'll have to agree with Stuart. Profiling dynamically
generated byte-code may not give you reliable numbers. It is better to
exclude generated classes from instrumentation target list and instead
measure the performance of classes that call generated code. Note that
I am only talking about CPU profiling. Memory is a different issue.
Have you tried different profiling modes (memory, CPU, code coverage)?
Are all of them failing?

+1 excluding generated bytecode from CPU profiling is a good idea

several profiling tools exclude CGLIB classes by default (ByCGLIB$$)
but Guice uses its own naming policy for proxies (ByGuice$$) which of
course means you need to remember to exclude these types yourself...
 

Yegor

On Mar 16, 11:23 am, Endre Stølsvik <stols...@gmail.com> wrote:
> Hi!
>
> Thanks for a very informative answer!
>
>
>
> > if CGLIB was generating invalid bytecode then I would expect to see
> > the verify error when you didn't use a profiler - so far I've only seen
> > this when profilers are involved...
>
> Well, the idea was that only when it came "last" to the code,
> transformations it yielded could end up wrong. Thus you would never
> observe an error with this as the sole tool. Also, one of the tools
> could be more robust than the other, so that it consistently handled
> being last, while the other didn't tackle that. Just musings..
>
> I think that CGLib should fix that "unusualness" of itself (apparently
> the number of explicit pops it sticks in before the multiple return
> points it generates?!), adhering to Postel's law: Be conservative in
> what you do; be liberal in what you accept from others. At least, it
> could have some switch that could produce conservative code (default),
> or drop this for the last bit of performance. And obviously, it might
> well be that it really is the other tools that are in error - but that
> isn't very helpful.
>
> Endre.

--
Cheers, Stuart

[Endre Stølsvik]

On Tue, Mar 17, 2009 at 15:49, Yegor <Yegor....@gmail.com> wrote:
>
> Aren't all profiling tools using the same Java Virtual Machine
> Profiling Interface? If so, we only have one CGLIB against one JVMPI,
> _not_ one CGLIB against many profiling tools. Profiling tools are
> merely front-ends that exchange events with JVMPI. So either CGLIB or
> JVMPI (or both) could be responsible for the error.

It is JVMTI (Tools Interface), which is a superset of both JVMPI and
JVMDI (Profiling and Debug, respectively).

And no: As a user of the TI's debug-mode, one just get the entire
class' bytecode "presented" before it is created into an actual class
(whatever internal representation the VM use), to jack it up with
whatever instrumentation one wants to stick in. So TI has nothing to
do with it - it is algorithms one use to instrument the class that
thus is at fault. And Stuart most certainly has a point: It thus is
the profiling system that "last touches" the class: I kinda thought
that TI /first/ manipulated the class, before it was passed through
the other classloaders and whatnot - something that obviously doesn't
make much sense at all.

Endre

[Andreas Petersson]

a small followup on this issue:

i tried to get profiler4j to work with guice, without success. excluding
*ByGuice* did not seem to work, my impression was, it does not allow
rules with two wildcards.
-Xverify:none did also not work, i just got a different error message,
also during startup, "invalid bytecode".

so i tried something simple: i downloaded the latest version of netbeans
6.5. after setting up the project correctly in netbeans (took about an
hour) it worked flawlessly. the netbeans debugger worked perfectly on
the exact same code profiler4j stumbled upon. the cglib classes did show
up in the profiler, although with no significant cpu/heap resources - i
did also find the cpu bottleneck i was facing - it was a simple issue of
excessive logging and rendering of sql statements. altering the log4j
parameters did fix this.

thanks so much for the suggestions in this thread!