5 Replies Latest reply on Jun 27, 2006 7:32 AM by kabirkhan

Strange regression in Proxy processing

adrian.brock May 3, 2006 9:01 AM

There seems to be a regression in the proxy processing.
It goes into a loop while trying to create the proxy.
But I only when running the test from inside eclipse?
Running from command line ant doesn't cause the problem.

It is looping somewhere here:

main" prio=1 tid=0x0805ff98 nid=0x2032 waiting on condition [0xbfeac000..0xbfeae168]
 at java.lang.String.<init>(String.java:208)
 at java.lang.StringBuilder.toString(StringBuilder.java:431)
 at java.io.UnixFileSystem.resolve(UnixFileSystem.java:93)
 at java.io.File.<init>(File.java:284)
 at sun.misc.URLClassPath$FileLoader.getResource(URLClassPath.java:891)
 at sun.misc.URLClassPath$FileLoader.findResource(URLClassPath.java:871)
 at sun.misc.URLClassPath.findResource(URLClassPath.java:142)
 at java.net.URLClassLoader$2.run(URLClassLoader.java:362)
 at java.security.AccessController.doPrivileged(Native Method)
 at java.net.URLClassLoader.findResource(URLClassLoader.java:359)
 at java.lang.ClassLoader.getResource(ClassLoader.java:977)
 at javassist.LoaderClassPath.find(LoaderClassPath.java:86)
 at javassist.ClassPoolTail.find(ClassPoolTail.java:317)
 at javassist.ClassPool.find(ClassPool.java:467)
 at javassist.ClassPool.createCtClass(ClassPool.java:451)
 at javassist.ClassPool.get0(ClassPool.java:417)
 - locked <0x88f1e8b8> (a javassist.ClassPool)
 at javassist.ClassPool.get0(ClassPool.java:426)
 - locked <0x88fbbdc8> (a org.jboss.aop.AOPClassPool)
 at javassist.ClassPool.get(ClassPool.java:386)
 at javassist.compiler.MemberResolver.lookupClass0(MemberResolver.java:415)
 at javassist.compiler.MemberResolver.lookupClass(MemberResolver.java:379)
 at javassist.compiler.MemberResolver.lookupClassByName(MemberResolver.java:306)
 at javassist.compiler.TypeChecker.atNewExpr(TypeChecker.java:95)
 at javassist.compiler.ast.NewExpr.accept(NewExpr.java:72)
 at javassist.compiler.CodeGen.doTypeCheck(CodeGen.java:235)
 at javassist.compiler.CodeGen.compileExpr(CodeGen.java:222)
 at javassist.compiler.CodeGen.atThrowStmnt(CodeGen.java:618)
 at javassist.compiler.CodeGen.atStmnt(CodeGen.java:358)
 at javassist.compiler.ast.Stmnt.accept(Stmnt.java:49)
 at javassist.compiler.CodeGen.atIfStmnt(CodeGen.java:384)
 at javassist.compiler.CodeGen.atStmnt(CodeGen.java:348)
 at javassist.compiler.ast.Stmnt.accept(Stmnt.java:49)
 at javassist.compiler.CodeGen.atStmnt(CodeGen.java:344)
 at javassist.compiler.ast.Stmnt.accept(Stmnt.java:49)
 at javassist.compiler.MemberCodeGen.atTryStmnt(MemberCodeGen.java:140)
 at javassist.compiler.CodeGen.atStmnt(CodeGen.java:360)
 at javassist.compiler.ast.Stmnt.accept(Stmnt.java:49)
 at javassist.compiler.CodeGen.atStmnt(CodeGen.java:344)
 at javassist.compiler.ast.Stmnt.accept(Stmnt.java:49)
 at javassist.compiler.CodeGen.atMethodBody(CodeGen.java:285)
 at javassist.compiler.Javac.compileBody(Javac.java:212)
 at javassist.CtBehavior.setBody(CtBehavior.java:282)
 at javassist.CtBehavior.setBody(CtBehavior.java:257)
 at javassist.CtNewMethod.make(CtNewMethod.java:135)
 at javassist.CtNewMethod.make(CtNewMethod.java:104)
 at org.jboss.aop.proxy.container.ContainerProxyFactory.createIntroductions(ContainerProxyFactory.java:571)
 at org.jboss.aop.proxy.container.ContainerProxyFactory.createMixinsAndIntroductions(ContainerProxyFactory.java:394)
 at org.jboss.aop.proxy.container.ContainerProxyFactory.addMethodsAndMixins(ContainerProxyFactory.java:361)
 at org.jboss.aop.proxy.container.ContainerProxyFactory.createProxyCtClass(ContainerProxyFactory.java:179)
 at org.jboss.aop.proxy.container.ContainerProxyFactory.createProxyCtClass(ContainerProxyFactory.java:159)
 at org.jboss.aop.proxy.container.ContainerProxyFactory.generateProxy(ContainerProxyFactory.java:131)
 at org.jboss.aop.proxy.container.ContainerProxyFactory.getProxyClass(ContainerProxyFactory.java:121)
 - locked <0x88fbbe10> (a java.lang.Object)
 at org.jboss.aop.proxy.container.GeneratedAOPProxyFactory.generateProxy(GeneratedAOPProxyFactory.java:115)
 at org.jboss.aop.proxy.container.GeneratedAOPProxyFactory.getProxy(GeneratedAOPProxyFactory.java:101)
 - locked <0x88f1e6c8> (a java.lang.Object)
 at org.jboss.aop.proxy.container.GeneratedAOPProxyFactory.createAdvisedProxy(GeneratedAOPProxyFactory.java:73)
 at org.jboss.aop.proxy.container.GeneratedAOPProxyFactory.createAdvisedProxy(GeneratedAOPProxyFactory.java:41)
 at org.jboss.rars.generic.mcf.GenericManagedConnectionFactory.createProxy(GenericManagedConnectionFactory.java:582)

You'll need to checkout the separate rars project from cvs
then run the src/tests/org.jboss.test.rars.RARAllTestSuite from inside eclipse.

1. Re: Strange regression in Proxy processing

kabirkhan May 9, 2006 5:36 AM (in response to adrian.brock)

I tried this and it works fine my end. I have just got back from training for the past week and a half, so I could have missed something, but I believe I have the right files checked out.
Actions

2. Re: Strange regression in Proxy processing

adrian.brock May 15, 2006 1:29 PM (in response to adrian.brock)

The issue appears to be something different in the way eclipse
does something (classloading?) and the way the command line does things.

The bottleneck is in CtNewMethod.make() in createIntroductions()

Eclipse:

6503 DEBUG [JDBCUnitTestCase] ==== Starting testNoTx ====
6539 DEBUG [GenericManagedConnection] org.jboss.rars.generic.mcf.GenericManagedConnection@5b0668[null] CREATED
7710 DEBUG [GenericBeanAspectFactory] Creating advice 3j001-q2b1dh-en92whoj-1-en92wi0t-8
7717 DEBUG [GenericBeanAspectFactory] Creating advice 3j001-q2b1dh-en92whoj-1-en92wi0a-7
7727 DEBUG [GenericBeanAspectFactory] Creating advice 3j001-q2b1dh-en92whoj-1-en92whzl-6
==========> generateProxy=56477ms
==========> requests=5
==========> createProxyCtClass=56365ms
==========> createBasics=2237ms
==========> addMethodsAndMixins=54103ms
==========> createMixinsAndIntroductions=54103ms
==========> createIntroductions=54088ms
==========> #CtNewMethod.make=389
==========> CtNewMethod.make=53468ms
==========> proxy.addMethod=74ms
63112 DEBUG [JDBCUnitTestCase] testNoTx took 56608ms
63113 DEBUG [JDBCUnitTestCase] ==== Stopping testNoTx ====

Command line

5067 DEBUG [GenericManagedConnection] org.jboss.rars.generic.mcf.GenericManagedConnection@10b9279[null] CREATED
5713 DEBUG [GenericBeanAspectFactory] Creating advice 3j001-og6y3q-en935jyu-1-en935kkh-8
5720 DEBUG [GenericBeanAspectFactory] Creating advice 3j001-og6y3q-en935jyu-1-en935kjr-7
5727 DEBUG [GenericBeanAspectFactory] Creating advice 3j001-og6y3q-en935jyu-1-en935kj6-6
11826 DEBUG [JDBCUnitTestCase] ==========> generateProxy=6047ms
11826 DEBUG [JDBCUnitTestCase] ==========> requests=5
11827 DEBUG [JDBCUnitTestCase] ==========> createProxyCtClass=5940ms
11827 DEBUG [JDBCUnitTestCase] ==========> createBasics=428ms
11827 DEBUG [JDBCUnitTestCase] ==========> addMethodsAndMixins=5490ms
11827 DEBUG [JDBCUnitTestCase] ==========> createMixinsAndIntroductions=5489ms
11827 DEBUG [JDBCUnitTestCase] ==========> createIntroductions=5489ms
11827 DEBUG [JDBCUnitTestCase] ==========> #CtNewMethod.make=389
11827 DEBUG [JDBCUnitTestCase] ==========> CtNewMethod.make=5067ms
11827 DEBUG [JDBCUnitTestCase] ==========> proxy.addMethod=65ms
11827 DEBUG [JDBCUnitTestCase] testNoTx took 6790ms

Eclipse ~ 137ms per method
Cmdline ~ 13ms per method

3. Re: Strange regression in Proxy processing

adrian.brock May 24, 2006 11:24 AM (in response to adrian.brock)

I think I've found the cause for this (well not exactly :-).
Most of the time is spent in the ClassPool/LoaderClassPath doing
ClassPool.get() then LoaderClassPath.find()

75369 DEBUG [JDBCUnitTestCase] CtNewMethodMakeTime=65342ms
75371 DEBUG [JDBCUnitTestCase] setBodyTime=65063ms
75371 DEBUG [JDBCUnitTestCase] getTime=63939ms
75371 DEBUG [JDBCUnitTestCase] findTime=57207ms
75371 DEBUG [JDBCUnitTestCase] find#=21931

It is trying to load a class called NoSuchMethodError (I think this should java.lang.NoSuchMethodError) 21245 times!

If I change the code in createIntroductions() to specify the full class name
then it becomes a lot faster:
9647 DEBUG [JDBCUnitTestCase] CtNewMethodMakeTime=2548ms
9648 DEBUG [JDBCUnitTestCase] setBodyTime=2507ms
9648 DEBUG [JDBCUnitTestCase] getTime=2365ms
9648 DEBUG [JDBCUnitTestCase] findTime=935ms
9649 DEBUG [JDBCUnitTestCase] find#=644
Actions
4. Re: Strange regression in Proxy processing

kabirkhan Jun 26, 2006 5:43 PM (in response to adrian.brock)

I have had a look at the InterceptorBinding.rebind() stuff.

When running within Eclipse, I found the same error you mention above - using a fully qualfied class name solved that in Eclipse.

Also, in the case of advices, an interceptor class is generated every time AdviceFactory.create() is called (when the interceptor chains are created either on startup or resulting from a rebind). I now check with the classloader if the class has already been created, and reuse that instead of regenerating every time.
Actions
5. Re: Strange regression in Proxy processing

kabirkhan Jun 27, 2006 7:32 AM (in response to adrian.brock)

I've set up the aop-mc tests to use

-Djboss.aop.exclude=org.jboss.
-Djboss.aop.include=org.jboss.test.

to avoid matching on every single loaded class
Actions

Go to original post