Avoid repeated superclass introspection in AnnotationUtils.findAnnotation [SPR-16730]

[spring-projects-issues]

Marc Boudreault opened SPR-16730 and commented

Hello,

We ran load tests and found that findAnnotation was one of the top method using CPU despite it uses caching.

We could correct this situation by caching NULL values with this simple change:

--- C:\Project\AnnotationUtils.java	2018-04-16 16:16:04.974657900 -0400
+++ C:\Project\src\main\java\org\springframework\core\annotation\AnnotationUtils.java	2018-03-12 16:58:54.540000000 -0400

@@ -136,6 +148,14 @@
 			new ConcurrentReferenceHashMap<Method, AliasDescriptor>(256);
 
 	private static transient Log logger;
+	
+	private static final Annotation NULL_ANNOTATION = new Annotation() {
+
+		@Override
+		public Class<? extends Annotation> annotationType() {
+			// TODO Auto-generated method stub
+			return null;
+		}};
 
 
 	/**
@@ -558,13 +578,14 @@
 	@SuppressWarnings("unchecked")
 	public static <A extends Annotation> A findAnnotation(Method method, Class<A> annotationType) {
 		Assert.notNull(method, "Method must not be null");
+		
 		if (annotationType == null) {
 			return null;
 		}
 
 		AnnotationCacheKey cacheKey = new AnnotationCacheKey(method, annotationType);
 		A result = (A) findAnnotationCache.get(cacheKey);
-
+		
 		if (result == null) {
 			Method resolvedMethod = BridgeMethodResolver.findBridgedMethod(method);
 			result = findAnnotation((AnnotatedElement) resolvedMethod, annotationType);
@@ -595,9 +616,13 @@
 			if (result != null) {
 				result = synthesizeAnnotation(result, method);
 				findAnnotationCache.put(cacheKey, result);
+			}else {
+				findAnnotationCache.put(cacheKey, NULL_ANNOTATION);
 			}
 		}
-
+		if(NULL_ANNOTATION == result) {
+			result = null;
+		}
 		return result;
 	}
 
@@ -691,8 +716,13 @@
 			if (result != null && synthesize) {
 				result = synthesizeAnnotation(result, clazz);
 				findAnnotationCache.put(cacheKey, result);
+			}else if(result == null && synthesize) {
+				findAnnotationCache.put(cacheKey, NULL_ANNOTATION);
 			}
 		}
+		if(NULL_ANNOTATION == result) {
+			result = null;
+		} 
 		return result;
 	}

Often findAnnotation returns null - adding a key with NULL_ANNOTATION as the value resolved the issue. NULL_ANNOTATION is reverted to null prior returning.

After this change we observed an appreciable 4-5% performance improvement in our app across the board.

---

Affects: 4.3.10

Issue Links:

• ReflectionUtils slow down application startup on WebSphere [SPR-11882] #16501 ReflectionUtils slow down application startup on WebSphere
• Performance regression on startup (in particular in AnnotationUtils) [SPR-13621] #18199 Performance regression on startup (in particular in AnnotationUtils)
• Comprehensively cache annotated methods for interfaces and superclasses [SPR-16675] #21216 Comprehensively cache annotated methods for interfaces and superclasses
• Annotations on generic interface methods not found by AnnotationUtils [SPR-16060] #20609 Annotations on generic interface methods not found by AnnotationUtils
• Cache order result per Class in OrderUtils (for AnnotationAwareOrderComparator) [SPR-17064] #21602 Cache order result per Class in OrderUtils (for AnnotationAwareOrderComparator)
• Avoid unnecessary synthesizable annotation processing [SPR-16933] #21472 Avoid unnecessary synthesizable annotation processing

Referenced from: commits d78e27f, 26652a6

[spring-projects-issues]

Juergen Hoeller commented

I suppose you have common stacktraces that are calling into findAnnotation there in your load tests? It'd be great to know where those are coming from and which methods are typically affected... Specifically, is the null caching particularly relevant for non-annotated methods or for methods with unrelated annotations?

[spring-projects-issues]

Juergen Hoeller commented

On review, this is very much the territory we've covered in #21216 for 5.0.5 already... primarily for AnnotatedElementUtils, missing the opportunity to leverage this in AnnotationUtils.findAnnotation as well. I've closed that gap for 5.0.6 now, repurposing this issue for it... since we intentionally don't cache null entries there, rather trying to optimize everything else so that such individual entries per method plus annotation type (which potentially leads to a very large number of entries if misses are recorded) can be avoided.

Let's see whether and where remaining expense can be optimized still, without caching every lookup attempt. Ideally, remaining hotspots should be cached at the caller's end, for example in MVC annotation processing... not repeatedly calling into findAnnotation for the same method to begin with. Any insight into your call patterns would be very helpful here!

Please give the upcoming 5.0.6.BUILD-SNAPSHOT a try if you have the chance. You might see some significant improvement with that approach already.

[spring-projects-issues]

Marc Boudreault commented

Here a typical call stack:

Stack for this key
@interface org.springframework.security.access.prepost.PreAuthorize on public abstract java.util.List com.myproject.cs.admin.viewpref.service.ViewPrefService.findApplicableViewOrSearch(java.lang.Long,java.lang.String,java.lang.String) throws com.myproject.framework.aop.interceptor.ServiceEntitlementException

TRACE: org.springframework.core.annotation.AnnotationUtils.findAnnotation(AnnotationUtils.java:630)
TRACE: com.myproject.framework.security.access.prepost.CSAPrePostAnnotationSecurityMetadataSource.findAnnotation(CSAPrePostAnnotationSecurityMetadataSource.java:94)
TRACE: com.myproject.framework.security.access.prepost.CSAPrePostAnnotationSecurityMetadataSource.getAttributes(CSAPrePostAnnotationSecurityMetadataSource.java:46)
TRACE: com.myproject.framework.security.access.method.CSAMethodSecurityMetadataSource.getAttributes(CSAMethodSecurityMetadataSource.java:47)
TRACE: com.myproject.framework.security.filters.DelegatingMethodDefinitionSource.getAttributes(DelegatingMethodDefinitionSource.java:82)
TRACE: org.springframework.security.access.intercept.AbstractSecurityInterceptor.beforeInvocation(AbstractSecurityInterceptor.java:174)
TRACE: org.springframework.security.access.intercept.aopalliance.MethodSecurityInterceptor.invoke(MethodSecurityInterceptor.java:60)

[spring-projects-issues]

Marc Boudreault commented

Here another one
Stack for this key @interface org.springframework.core.annotation.Order on class org.apache.cxf.bus.spring.SpringBus$1

TRACE: org.springframework.core.annotation.AnnotationUtils.findAnnotation(AnnotationUtils.java:806)
TRACE: org.springframework.core.annotation.AnnotationUtils.findAnnotation(AnnotationUtils.java:751)
TRACE: org.springframework.core.annotation.OrderUtils.getOrder(OrderUtils.java:69)
TRACE: org.springframework.core.annotation.OrderUtils.getOrder(OrderUtils.java:57)
TRACE: org.springframework.core.annotation.AnnotationAwareOrderComparator.findOrder(AnnotationAwareOrderComparator.java:85)
TRACE: org.springframework.core.OrderComparator.getOrder(OrderComparator.java:127)
TRACE: org.springframework.core.OrderComparator.getOrder(OrderComparator.java:116)
TRACE: org.springframework.core.OrderComparator.doCompare(OrderComparator.java:88)
TRACE: org.springframework.core.OrderComparator.compare(OrderComparator.java:73)
TRACE: java.util.TimSort.countRunAndMakeAscending(TimSort.java:360)
TRACE: java.util.TimSort.sort(TimSort.java:220)
TRACE: java.util.Arrays.sort(Arrays.java:1438)
TRACE: java.util.List.sort(List.java:478)
TRACE: java.util.Collections.sort(Collections.java:175)
TRACE: org.springframework.core.annotation.AnnotationAwareOrderComparator.sort(AnnotationAwareOrderComparator.java:124)
TRACE: org.springframework.context.event.AbstractApplicationEventMulticaster.retrieveApplicationListeners(AbstractApplicationEventMulticaster.java:243)
TRACE: org.springframework.context.event.AbstractApplicationEventMulticaster.getApplicationListeners(AbstractApplicationEventMulticaster.java:185)
TRACE: org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:127)
TRACE: org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:383)
TRACE: org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:337)

[spring-projects-issues]

Marc Boudreault commented

Here some stats on how many times we avoided going deep through findAnnotation calls with NULL_ANNOTATION, just after a few clicks on the application (no smoking test here)

@interface org.springframework.core.annotation.Order on class com.myproject.caching.support.CsaOsCacheInterceptor=13506, 
@interface org.springframework.core.annotation.Order on class org.apache.cxf.bus.spring.SpringBus$1=13505, 
@interface org.springframework.core.annotation.Order on class com.myproject.framework.resource.refresh.serviceentitlement.ServiceEntitlementBundle=13505, 
@interface org.springframework.core.annotation.Order on class com.myproject.framework.resource.refresh.departmentbundle.DepartmentBundle=13505, 
@interface javax.annotation.Priority on class com.myproject.framework.resource.refresh.departmentbundle.DepartmentBundle=13505, 
@interface javax.annotation.Priority on class com.myproject.framework.resource.refresh.fields.FieldsBundle=13505, 
@interface org.springframework.core.annotation.Order on class com.sun.proxy.$Proxy399=13505, 
@interface javax.annotation.Priority on class com.sun.proxy.$Proxy398=13505, 
@interface org.springframework.core.annotation.Order on class com.sun.proxy.$Proxy393=13505, 
@interface org.springframework.core.annotation.Order on class com.sun.proxy.$Proxy400=13505, 
@interface javax.annotation.Priority on class com.myproject.framework.resource.refresh.resourcebundle.ResourceBundle=13505, 
@interface javax.annotation.Priority on class com.sun.proxy.$Proxy330=13505, 
@interface org.springframework.core.annotation.Order on class com.myproject.cs.admin.webnote.managedservice.NotificationListener=13505, 
@interface org.springframework.core.annotation.Order on class com.myproject.cs.security.captcha.store.IAFCaptchaEventListener=13505, 
@interface javax.annotation.Priority on class com.myproject.framework.resource.refresh.settingbundle.SettingBundle=13505, 
@interface javax.annotation.Priority on class com.myproject.cs.admin.theme.DBSentinelThemeSynchronizer=13505, 
@interface javax.annotation.Priority on class com.sun.proxy.$Proxy397=13505, 
@interface org.springframework.core.annotation.Order on class com.myproject.cs.admin.theme.DBSentinelThemeSynchronizer=13505, 
@interface javax.annotation.Priority on class com.myproject.framework.remote.BundleCachingAdvice=13505, 
@interface org.springframework.core.annotation.Order on class com.sun.proxy.$Proxy397=13505, 
@interface javax.annotation.Priority on class com.sun.proxy.$Proxy396=13505, 
@interface javax.annotation.Priority on class com.sun.proxy.$Proxy399=13505, 
@interface org.springframework.core.annotation.Order on class com.myproject.framework.remote.BundleCachingAdvice=13505, 
@interface javax.annotation.Priority on class com.myproject.framework.resource.refresh.assignablebundle.AssignableBundle=13505, 
@interface javax.annotation.Priority on class com.myproject.cs.security.captcha.store.IAFCaptchaEventListener=13505, 
@interface org.springframework.core.annotation.Order on class com.myproject.framework.resource.refresh.configbundle.ConfigBundle=13505, 
@interface org.springframework.core.annotation.Order on class com.myproject.framework.resource.refresh.fields.FieldsBundle=13505, 
@interface javax.annotation.Priority on class com.myproject.framework.resource.refresh.serviceentitlement.ServiceEntitlementBundle=13505, 
@interface org.springframework.core.annotation.Order on class com.myproject.framework.resource.refresh.assignablebundle.AssignableBundle=13505, 
@interface org.springframework.core.annotation.Order on class com.myproject.framework.resource.refresh.settingbundle.SettingBundle=13505, 
@interface javax.annotation.Priority on class com.sun.proxy.$Proxy401=13505, 
@interface javax.annotation.Priority on class com.sun.proxy.$Proxy393=13505, 
@interface javax.annotation.Priority on class com.sun.proxy.$Proxy394=13505, 
@interface org.springframework.core.annotation.Order on class com.sun.proxy.$Proxy396=13505, 
@interface org.springframework.core.annotation.Order on class com.sun.proxy.$Proxy330=13505, 
@interface javax.annotation.Priority on class org.apache.cxf.bus.spring.SpringBus$1=13505, 
@interface javax.annotation.Priority on class com.myproject.framework.resource.refresh.resourcebundle.ResourceFileBundle=13505, 
@interface org.springframework.core.annotation.Order on class com.sun.proxy.$Proxy394=13505, 
@interface org.springframework.core.annotation.Order on class com.sun.proxy.$Proxy398=13505, 
@interface javax.annotation.Priority on class org.apache.camel.spring.CamelContextFactoryBean=13505, 
@interface javax.annotation.Priority on class com.myproject.framework.resource.refresh.configbundle.ConfigBundle=13505,
@interface org.springframework.core.annotation.Order on class com.myproject.framework.resource.refresh.resourcebundle.ResourceFileBundle=13505, 
@interface org.springframework.core.annotation.Order on class com.myproject.framework.resource.refresh.resourcebundle.ResourceBundle=13505, 
@interface org.springframework.core.annotation.Order on class com.sun.proxy.$Proxy401=13505, 
@interface javax.annotation.Priority on class com.myproject.cs.admin.webnote.managedservice.NotificationListener=13505, 
@interface javax.annotation.Priority on class com.myproject.caching.support.CsaOsCacheInterceptor=13505, 
@interface org.springframework.core.annotation.Order on class org.apache.camel.spring.CamelContextFactoryBean=13505, 
@interface javax.annotation.Priority on class com.sun.proxy.$Proxy400=13505, @interface javax.annotation.Priority on class com.myproject.framework.monitoring.caching.CacheMonitoring=13339, 
@interface org.springframework.core.annotation.Order on class com.myproject.framework.monitoring.caching.CacheMonitoring=13339, 
@interface org.springframework.core.annotation.Order on class com.myproject.eventbroadcaster.factory.FailSafeEventBroadcasterFactory=6756, 
@interface javax.annotation.Priority on class com.myproject.eventbroadcaster.factory.FailSafeEventBroadcasterFactory=6755, 
@interface org.springframework.core.annotation.Order on class com.myproject.monitoring.events.EventsMonitor=6753, 
@interface javax.annotation.Priority on class com.myproject.monitoring.events.EventsMonitor=6753, 
@interface org.springframework.security.access.prepost.PreAuthorize on class com.myproject.framework.base.service.impl.ServiceImpl=31, 
@interface org.springframework.security.access.prepost.PostFilter on class com.myproject.framework.base.service.impl.ServiceImpl=31, 
@interface org.springframework.security.access.prepost.PreFilter on class com.myproject.framework.base.service.impl.ServiceImpl=31, 
@interface org.springframework.security.access.prepost.PostAuthorize on class com.myproject.framework.base.service.impl.ServiceImpl=31, 

[spring-projects-issues]

Marc Boudreault commented

Thx for addressing this quickly. Will give it a try as soon as possible.

[spring-projects-issues]

Juergen Hoeller commented

Interesting, so it's primarily sorting by order annotations. I wouldn't have expected that to show up so strongly. I'll see what we can do about locally caching annotation-determined order values in AnnotationAwareOrderComparator.

[spring-projects-issues]

Marc Boudreault commented

I have retested with latest 5.0.6 spring version and findAnnotations still shows on top of the list, where as, with the null cache patch it uses almost no cpu.

  !image-2018-06-04-16-21-39-314.png!

[spring-projects-issues]

Juergen Hoeller commented

I'm finally sorting out the AnnotationAwareOrderComparator case in #21602.

[spring-projects-issues]

Marc Boudreault commented

We have upgraded to spring 5.1.1 and I can confirm the issue is fixed.

Thx!