AopUtils#findAdvisorsThatCanApply can be slow with larger number of Aspects

[caitsithx]

In the application I'm currently working with, there are 7534 beans and 115 AOP aspects. However, I've noticed that the startup time of the Spring context is quite slow. After conducting some testing and profiling, I have identified an area that can be optimized: the org.springframework.aop.support.AopUtils#findAdvisorsThatCanApply method. This method sequentially determines which AOP advisors from a list of candidates are applicable for a specific bean class. This process occurs within the Spring initialization thread.

To improve the performance, I made some modifications to parallelize the determination process at the granularity of one candidate advisor. I then measured the number of method calls, the average execution time, and the total execution time of this method during the Spring startup for both the original and improved code. here is the result:

[jhoeller]

We intend to revisit core container performance concerns in 6.2 (see e.g. #28122), so let's see what we can do about AOP Advisor matching. In general, we are very controlled in terms of thread usage and rather concerned about locking effects (see e.g. #23501), so it would be very unusual for us to use parallel collection streams there.

That said, for applications with such large numbers of beans and aspects, we might be able to find a different arrangement with a similar performance effect. I've put this issue into 6.2.x for that reason.

[jhoeller]

One further note on parallel processing there is the order of the outcome. In general, we treat advisors as per their registration order. With parallel streams, we cannot guarantee that the eligibleAdvisors list is being populated in registration order, aside from having to be a thread-safe collection type if it is being accessed from multiple threads.

The key question is why AopUtils.canApply is so expensive here to begin with. I assume it is the method matching - but even there I wonder whether it is the iteration over ReflectionUtils.getAllDeclaredMethods that turns out to be expensive in case of many methods, or whether it is the actual MethodMatcher.matches calls themselves.

Which aspects are involved in your scenario with >100 aspects? AspectJExpressionPointcut possibly which needs to match a pointcut expression against every given method, being the most obvious candidate for an expensive step with a lot of CPU cycles here? If so, we should try to optimize AspectJExpressionPointcut for faster matching, and in particular for faster non-matching if we spend too much time matching a pointcut expression against many non-matching methods...

[jhoeller]

Assuming that your advisors are mostly of type AspectJExpressionPointcut, could you provide a few examples for the pointcut expressions that you are declaring there? AspectJ matching performance rather strongly depends on the kind of pointcut, after all.

[jhoeller]

For wildcard type matches, there is https://bugs.eclipse.org/bugs/show_bug.cgi?id=532033 from six years ago which unfortunately never got released, apparently due to breaking Spring Framework tests - which I cannot reproduce (anymore), our spring-aop test suite passes with the suggested patch applied to the AspectJ KindedPointcut class. So maybe the AspectJ project should roll that patch into a release indeed, you could start that conversation with them through commenting on their bug tracker.

With the current AspectJ 1.9.21, the patch is simply to uncomment lines 178-181 in KindedPointcut:
https://github.com/eclipse-aspectj/aspectj/blob/1dd77e04e8a7221af03bb5235ebae036e0d21ba6/org.aspectj.matcher/src/main/java/org/aspectj/weaver/patterns/KindedPointcut.java#L178
Simply adding a copy of that class with that block uncommented to your project classpath should make it override the class from the original AspectJ jar; this is how I tested it locally as well. The effect should be immediately noticeable since it completely bypasses per-method matching on classes where the aspect does not apply based on the declaring class at all.

In my investigation, I have not found any other advisor matching scenario with the same magnitude of performance expense. With the above AspectJ patch applied, there should be no need for parallel advisor checking anymore, at least not with AspectJExpressionPointcut as the main culprit. It would be great if you could confirm the effect of that patch from your side.

[sbrannen]

For wildcard type matches, there is https://bugs.eclipse.org/bugs/show_bug.cgi?id=532033 from six years ago which unfortunately never got released, apparently due to breaking Spring Framework tests - which I cannot reproduce (anymore), our spring-aop test suite passes with the suggested patch applied to the AspectJ KindedPointcut class. So maybe the AspectJ project should roll that patch into a release indeed, you could start that conversation with them through commenting on their bug tracker.

If you don't receive any feedback on that old issue, please note that the current AspectJ issue tracker is now on GitHub: https://github.com/eclipse-aspectj/aspectj/issues

[jhoeller]

A quick follow-up: We actually do have test failures in the test suite when the AspectJ patch is applied but not in the core AOP tests, rather in AopNamespaceHandlerTests for XML and GroovyScriptFactoryTests. I intend to investigate those later this week.

[edavedian]

@jhoeller Thank you so much for your analysis and suggestions above. We are currently using Spring Framework 5.8.5 and I upgraded our aspectj dependency to 1.9.21 and included a copy of KindedPointcut in our project with the uncommented code as you suggested. This seems to eliminate the long startup time we were experiencing with our project due to a lot of beans with a lot methods and a lot of aspects.
The comment in KindedPointcut states // Optimization from 532033: passes AspectJ tests but breaks Spring Framework and you also confirmed there are test failures. If you are able to figure out what regression this is causing in Spring and address it, that would greatly help us and I am sure many other teams/applications in a similar state. If the regression is addressed in Spring, then we can coordinate with aspectj to make the patch official.
Could I ask you to please let us know if including the KindedPointcut in our project is a wise idea given the test failures in Spring?

[edavedian]

@jhoeller My apologies but after further testing I realized today that just upgrading aspectj dependency to 1.9.21 for us was sufficient to improve the long startup time. I also tested with KindedPointcut and uncommented code but that didn't significantly improve on top of what upgrading the aspectj dependency had already improved. My apologies again for the confusion.

[jhoeller]

That if block in KindedPointcut is still commented out as of AspectJ 1.9.21.1, so there must be some other change improving the matching performance there. @edavedian, great to hear that this sufficiently addresses your scenario for a start! AspectJ 1.9.21.1 also passes all our our tests so far.

@caitsithx any chance you could re-run your benchmark scenario against AspectJ 1.9.21.1? It'd be great to understand whether there is a significant enough performance problem remaining. If that is still the case, we need to follow up with the AspectJ team to see what it takes to uncomment that block in KindedPointcut without causing any test failures.

[jhoeller]

A quick update: AspectJ 1.9.22 is out in the meantime, so please rather re-run your benchmarks against that version.

[jhoeller]

I assume there is nothing more we can do about this from the Spring Framework side. For any further benchmarks, please run them against the latest AspectJ version and let us know if there is still anything to advocate for there.

[bironran]

Re the KindedType fix with WildTypePattern.match:
copied from eclipse-aspectj/aspectj@afaa961#r152252243:

This doesn't actually work well. Consider negative composite patterns, e.g. a.b.c and !@annotation a.b.c. Because you only consider the pattern type, you miss on annotations.

The right part !@annotation a.b.c will answer "yes" on "a.b.c." (sans annotation) but should answer "maybe yes" because the true answer is "no" without the annotation this doesn't match the right. When negative, this can make a weaving not happen when it should.