Per Instance Aspects Overhead

[flavia.rainone]

Regarding the JBoss Messaging clustering tests (see previous discussion here http://www.jboss.com/index.html?module=bb&op=viewtopic&t=133377), I have found out what is causing all the overhead.

Since there are per instance aspects involved, InstanceAdvisors get created during the first time the intercepted methods get executed. This happens on the getAround1() method of the generated JoinPoint class, which creates the aspect instance to perform interception.

However, once the class advisor is replaced by an instance advisor, a request for a new JoinPoint class is made to the JoinPointGenerator (this is done by the wrapper created by GeneratedAdvisorMethodExecutionTransformer).
Notice that there are no dynamic AOP actions involved, which means that we would be fine if we used the previously generated joinpoint class.
However, this is not what is happening. Since the JoinPointGenerator used by the InstanceAdvisor is different from the JoinPointGenerator previous used to generate the initial JoinPoint class, there won't be any generated class in the JoinPointGenerator cache, which triggers a joinpoint class generation for each instance of the intercepted class. This explains the amazing amount of class generations we were seeing.

I am going to share the JoinpointGenerator among the instance advisors, and I am going to share it betwen those advisors and class advisor as well. That will avoid creation of extra JoinPoint classes, which should diiminish the overhead.

[flavia.rainone]

We could see a better yet performance if we don't reset the joinpoint instance when an instance advisor gets created. Kabir, do you think this would break something?

This would imply that a joinpoint class generation request is made only when necessary, i.e., the first time the joinpoint is reached, and when there is a new interception chain, different from the previous chain.

For that, we will need to be able of asserting whether the interceptor chain in the instance advisor is any different from the one in the class advisor.

[kabirkhan]

Hi Flavia,

I think what you suggest sounds fine. Try it out and see if our tests still pass.

I committed some code I had lying around to compare JoinPointInfos. Take a look at Advisor.hasSameMethodAspects(). This is completely untested, so please modify as you see fit.

[flavia.rainone]

I was wrong regarding the JoinPointGenerator unshared instances. As a matter of fact, they are shared between the intance advisors and the class advisor.

What was happening was a a bug inserted during implementation of JBAOP-550:

http://jira.jboss.com/jira/browse/JBAOP-562

I'm about to commit the fix for JBAOP-562. However, the jboss messaging tests still fail. What I am seeing here is 3418ms spent on 513 invocations to JoinPointGenerator.generateJoinPointClass. Taking a deeper look, a 2898ms parcel of this time is spent on the generation of 29 joinpoint classes. The rest is spent on retrieving generated classes from the cache and calls to reload the generated class from the class loader.

The time spent in the generation of joinpoint classes could be hardly be optimized, IMO. 1153ms are spent alone in 29 calls to JoinPointGenerator.initialiseAdviceInfosAndAddFields, 741ms of which are spent in the JoinPointGenerator.addAspectFieldAndGetter() method. The main overhead of this method is in the call to CtNewMethod.make() method, of javassist (691ms). The 1153ms also include 199 ms spent on 66 calls to the AdviceMethodFactory.findAdviceMethod. I am not sure we can optimize something inside it either (need to take a deeper look). Finally, there are 150 ms spent alone on the constructor of AdviceSetup. Most of the overhead of this constructor lies in calls to ClassLoader.loadClass and to ReflectToJavassist.classToJavassist. The rest of these 1153ms are micro seconds spent here and there with other operations.

Second in the overhead list of joinpoint classes generation are the 919ms spent on 29 invocations to JoinPointGenerator.createConstructors. Most of this overhead is caused by the calls to CtNewConstructor.make javassist methods.

I wonder whether it is worth to optimize the joinpoint class generation, or if it would be better to concentrate on turning the 513 invocations to JoinPointGenerator.generateJoinPointClass into aprox 29 calls.

Any ideas?

[dimitris]

FYI, with aop 2.0.0.CR9 (and probably CR8, too), the start-up time of jboss has gone up again with the default config booting in ~50 secs. It used to be ~30 secs.

We need to optimize, somehow:

http://jira.jboss.com/jira/browse/JBAS-5224

[kabirkhan]

Posted to another mailing list

The one thing I can think of that could down AS startup recently is http://jira.jboss.com/jira/browse/JBAS-5495. This is however a necessary fix if we are to be able to have dynamic aop for proxies for things like ArrayList etc. Basically it means there are more advisors/sub-domains to iterate over when adding bindings.

I have asked Staale to profile the startup of AS to see if this is us.