Major performance slowdown in AnnotationUtils.findAnnotation [SPR-7630]

[spring-projects-issues]

Stéphane Nicoll opened SPR-7630 and commented

While migrating our app from 2.5.7 to 3.0.4 we have noticed a major slowdown in the application context's startup.

Our application is using Spring Batch and has 22 batches. I have ran a profiling session and noticed an abusive call to java.lang.Class.getMethod(String, Class[]).

The culprit seems to be a change in AnnotationUtils.findAnnotation(Method,Class).

Attached the back trace calls for both Spring 2.5 and 3.0.4. The only thing that changed between the profiling sessions is the Spring version and the profiler only starts the (same) application context.

I also have the yourkit snapshots if you are interested to run a snapshot comparison.

This is obviously blocking us to upgrade. Let me know if there anything I can do to help.

---

Affects: 3.0.4

Reference URL: http://forum.springsource.org/showthread.php?p=323388#post323388

Attachments:

• spring25-batch-register-step-listeners-call-stack.png (108.12 kB)
• spring25-getMethod.png (19.30 kB)
• spring25-register-item-listeners-call-stack.png (91.53 kB)
• spring-3.0.4.xls (594.00 kB)
• spring-3.0.5-SNAP-getMethod.PNG (16.06 kB)
• spring-3.0.5-SNAP-register-item-listeners-call-stack.png (46.23 kB)
• spring3-getMethod.png (59.53 kB)
• spring3-register-item-listeners-call-stack.png (67.84 kB)
• spring3-register-step-listeners-call-stack.png (66.47 kB)

Issue Links:

• ReflectionUtils slow down application startup on WebSphere [SPR-11882] #16501 ReflectionUtils slow down application startup on WebSphere
• Comprehensively cache annotated methods for interfaces and superclasses [SPR-16675] #21216 Comprehensively cache annotated methods for interfaces and superclasses

Referenced from: commits 3c067e5

1 votes, 5 watchers

[spring-projects-issues]

Juergen Hoeller commented

Of those 1.3 million calls, how often is this being invoked for the very same method signatures and target interfaces? I suppose you got many objects which implement the same interfaces but never actually contain annotations on any interface method? Are only the interfaces the same, or the searched classes as well?

Juergen

[spring-projects-issues]

Stéphane Nicoll commented

Spring batch listener registration (spring 3)

[spring-projects-issues]

Stéphane Nicoll commented

Spring batch listener registration (spring 2.5)

[spring-projects-issues]

Stéphane Nicoll commented

arguments of getMethodInvokerByAnnotation with Spring 3

[spring-projects-issues]

Stéphane Nicoll commented

I attached everything I found relevant for you. If you look at the call stack, most of the getMethod calls are from the Spring batch listeners registration process (registerStepListeners and registerItemListeners respectively).

Eventually, both end up in org.springframework.batch.support.getMethodInvokerByAnnotation(final Class<? extends Annotation> annotationType, final Object target).

I have attached every call to this method in the attached excel file (ugh!). The first column is the class name of the object (or proxy around it) and the second column is the required annotation type. You'll see by yourself but it seems it is called four times for the same annotation and the same target (actually 2 times for the step listener registration and 2 times for the item listener registration).

I don't know if we can avoid this duplication (Dave might definitely have more insight) but the difference between 2.5 and 3.0 is obvious and is located in Spring core. I have attached the call stack of the same registration process with Spring 2.5 for you to compare.

Is this enough?

Thanks!

[spring-projects-issues]

Stéphane Nicoll commented

And to answer your question, for one part of the registration we have 2224 calls (you will find the details in the excel sheet) leading to 67488 invocations of the AnnotationUtils.findAnnotation. These 67488 invocations lead to half a million getMethod calls roughly.

We might be able to cache this information in Spring batch and reduce the number of calls from 2224 to 556. I have no idea if things could be cached as well in the core framework itself.

[spring-projects-issues]

Juergen Hoeller commented

Thanks for the additional context, Stephane - that definitely brings us one step further.

The change in Spring 3.0 is that we're searching for annotations on implemented interfaces as well, i.e. on methods with the same signature as the one we're given, declared on any implemented interface. This involves getMethod calls for the signature check, and this seems to be making the difference in your case. I wonder how many interfaces your objects implement as they are being given to AnnotationUtils.findAnnotation... Probably always the same Spring batch callback interfaces? Spring 3.0 would search those interfaces for annotations again and again, which of course is in vain since it'll never find an annotation on those.

Juergen

[spring-projects-issues]

Stéphane Nicoll commented

Juergen,

I ran another profiling session to get the details and here's some output (it's not fully complete but you have most of the objects being involved in the initial excel sheet.

• Proxy50 (ItemReader) has 64 calls and implements interface org.springframework.batch.item.ItemReader, interface com.bsb.sf.batch.configuration.parameter.ParameterResolverAware, interface org.springframework.batch.core.StepExecutionListener, interface java.io.Serializable, interface org.springframework.aop.scope.ScopedObject, interface org.springframework.aop.framework.AopInfrastructureBean, interface org.springframework.aop.SpringProxy, interface org.springframework.aop.framework.Advised
• Proxy52 (ItemWriter) has 927 calls and implements interface org.springframework.batch.item.ItemWriter, interface org.springframework.batch.core.StepExecutionListener, interface org.springframework.beans.factory.InitializingBean, interface java.io.Serializable, interface org.springframework.aop.scope.ScopedObject, interface org.springframework.aop.framework.AopInfrastructureBean, interface org.springframework.aop.SpringProxy, interface org.springframework.aop.framework.Advised
• Proxy51 (ItemProcessor) has 1024 calls and implements interface org.springframework.batch.core.StepExecutionListener, interface org.springframework.batch.core.ChunkListener, interface org.springframework.beans.factory.InitializingBean, interface org.springframework.batch.item.ItemProcessor, interface java.io.Serializable, interface org.springframework.aop.scope.ScopedObject, interface org.springframework.aop.framework.AopInfrastructureBean, interface org.springframework.aop.SpringProxy, interface org.springframework.aop.framework.Advised
• Proxy59 (StagingItemReader) has 927 calls and implements interface org.springframework.batch.item.ItemReader, interface org.springframework.batch.core.ItemReadListener, interface org.springframework.batch.core.StepExecutionListener, interface org.springframework.beans.factory.InitializingBean, interface java.io.Serializable, interface org.springframework.aop.scope.ScopedObject, interface org.springframework.aop.framework.AopInfrastructureBean, interface org.springframework.aop.SpringProxy, interface org.springframework.aop.framework.Advised
• Proxy 56 (ItemReader) has 63 calls and implements interface org.springframework.beans.factory.InitializingBean, interface org.springframework.batch.item.ItemReader, interface org.springframework.batch.item.ItemStream, interface java.io.Serializable, interface org.springframework.aop.scope.ScopedObject, interface org.springframework.aop.framework.AopInfrastructureBean, interface org.springframework.aop.SpringProxy, interface org.springframework.aop.framework.Advised
• Proxy 58 (StagingItemWriter) has 507 calls and implements interface org.springframework.batch.core.StepExecutionListener, interface org.springframework.batch.core.ItemWriteListener, interface org.springframework.batch.item.ItemWriter, interface java.io.Serializable, interface org.springframework.aop.scope.ScopedObject, interface org.springframework.aop.framework.AopInfrastructureBean, interface org.springframework.aop.SpringProxy, interface org.springframework.aop.framework.Advised
• Proxy 57 (StagingItemProcessor) has 415 calls and implements interface com.bsb.sf.batch.item.staging.StagingItemProcessor, interface java.io.Serializable, interface org.springframework.aop.scope.ScopedObject, interface org.springframework.aop.framework.AopInfrastructureBean, interface org.springframework.aop.SpringProxy, interface org.springframework.aop.framework.Advised
• Proxy 67 (ItemReader) has 447 calls and implements interface com.bsb.sf.batch.service.monitoring.MonitorableItemReader, interface org.springframework.batch.item.ItemReader, interface org.springframework.batch.item.ItemStream, interface org.springframework.batch.core.StepExecutionListener, interface org.springframework.beans.factory.InitializingBean, interface java.io.Serializable, interface org.springframework.aop.scope.ScopedObject, interface org.springframework.aop.framework.AopInfrastructureBean, interface org.springframework.aop.SpringProxy, interface org.springframework.aop.framework.Advised
• Proxy 73 (ItemReader) has 32 calls and implements interface org.springframework.batch.item.ItemReader, interface com.bsb.sf.batch.test.support.exception.ExceptionThrowerListener, interface org.springframework.beans.factory.InitializingBean, interface com.bsb.sf.batch.configuration.parameter.ParameterResolverAware, interface org.springframework.batch.core.StepExecutionListener, interface java.io.Serializable, interface org.springframework.aop.scope.ScopedObject, interface org.springframework.aop.framework.AopInfrastructureBean, interface org.springframework.aop.SpringProxy, interface org.springframework.aop.framework.Advised
• class com.bsb.sf.batch.service.partition.BusinessPolicyStagingProcessor has 31 calls and implements interface com.bsb.sf.batch.item.staging.StagingItemProcessor
• class com.bsb.sf.batch.test.item.AccountExceptionTestReader has 190 calls and implements interface org.springframework.batch.item.ItemReader, interface com.bsb.sf.batch.test.support.exception.ExceptionThrowerListener, interface org.springframework.beans.factory.InitializingBean, interface com.bsb.sf.batch.configuration.parameter.ParameterResolverAware, interface org.springframework.batch.core.StepExecutionListener, interface java.io.Serializable, interface org.springframework.aop.scope.ScopedObject, interface org.springframework.aop.framework.AopInfrastructureBean
• class com.bsb.sf.batch.test.item.AccountExceptionTestWriter has 190 calls and implements interface com.bsb.sf.batch.test.support.exception.ExceptionThrowerListener, interface org.springframework.beans.factory.InitializingBean, interface org.springframework.batch.item.ItemWriter, interface com.bsb.sf.batch.configuration.parameter.ParameterResolverAware, interface org.springframework.batch.core.StepExecutionListener, interface java.io.Serializable, interface org.springframework.aop.scope.ScopedObject, interface org.springframework.aop.framework.AopInfrastructureBean

From what I can see we search for annotations on the proxy, which seems weird to me (ScopedObject, AopInfrastructureBean, Advised, SpringProxy). It has 25 methods (23 only in Advised!).

I also think that this change in Spring 3 is probably against what is done in Spring Batch since these annotations are not meant (IMHO) to be put on an interface: they are primarily used as callback tags for listener events.

[spring-projects-issues]

Dave Syer commented

Maybe Spring could do some caching? In this case it would help to aggressively cache negative results: if a method has no annotations it can be ignored on all subsequent calls.

[spring-projects-issues]

Juergen Hoeller commented

I've finally addressed this through caching of interfaces in AnnotationUtils: We're storing whether a given interface has any methods with annotations in a static WeakHashMap. This shouldn't cause issues with garbage collection since the values are plain booleans, so there are no references back to the keys.

I hope this actually provides the speed-up that you're expecting. It's the best we can do without changing semantics. This will be available in tomorrow morning's 3.0.5 snapshot.

Juergen

[spring-projects-issues]

Stéphane Nicoll commented

Great! This fixes indeed the underlying issue.

Some facts about my simple test that bootstrap the container:

• Spring 2.5.7: ~11 sec
• Spring 3.0.4: ~32 sec
• Spring 3.0.5.BUILD-20101015.013605-74: ~12 sec

Also attached relevant back trace that shows the problem is fixed for my use case.

Thanks Juergen!