Annotated method argument matching performance issue [SPR-15060]

[spring-projects-issues]

Gary Russell opened SPR-15060 and commented

Possibly related to #19496

@SpringBootApplication
public class So41346616Application {

	public static void main(String[] args) {
		ConfigurableApplicationContext context = SpringApplication.run(So41346616Application.class, args);
		MessageChannel annotated = context.getBean("annotated", MessageChannel.class);
		MessageChannel notAnnotated = context.getBean("notAnnotated", MessageChannel.class);
		Message<?> foo = new GenericMessage<>("foo");
		StopWatch watch = new StopWatch();
		watch.start();
		for (int i = 0; i < 10000; i++) {
			annotated.send(foo);
		}
		watch.stop();
		watch.start();
		for (int i = 0; i < 10000; i++) {
			notAnnotated.send(foo);
		}
		watch.stop();
		watch.start();
		for (int i = 0; i < 10000; i++) {
			annotated.send(foo);
		}
		watch.stop();
		System.out.println("Annotated: " + watch.getTaskInfo()[0].getTimeMillis() +
				" not: " + watch.getTaskInfo()[1].getTimeMillis() +
				" second annotated: " + watch.getTaskInfo()[2].getTimeMillis());
		context.close();
	}

	@ServiceActivator(inputChannel = "annotated")
	public void with(@Payload String payload) {
	}

	@ServiceActivator(inputChannel = "notAnnotated")
	public void without(String payload) {
	}

}

Annotated: 3521 not: 36 second annotated: 11202

Yourkit pointed me to ConcurrentReferenceHashMap and we're getting cache misses and adding new entries for each invocation.

---

Affects: 4.3.5

Reference URL: http://stackoverflow.com/questions/41346616/spring-boot-starter-integration-1-4-3-performance-degradation

Attachments:

• Screen Shot 2016-12-27 at 10.36.03 AM.png (247.62 kB)
• Screen Shot 2016-12-27 at 12.13.01 PM.png (187.09 kB)

Issue Links:

• Performance Issue with @ModelAttribute [SPR-15198] #19762 Performance Issue with @ModelAttribute ("is duplicated by")
• ConversionService performance regression [SPR-14929] #19496 ConversionService performance regression
• AnnotationFormatterFactory should support @AliasFor [SPR-14844] #19410 AnnotationFormatterFactory should support @AliasFor
• Improve performance for conversions using a method parameter based type descriptor with annotations [SPR-14926] #19493 Improve performance for conversions using a method parameter based type descriptor with annotations

Referenced from: commits e38c020, 794580f

3 votes, 9 watchers

[spring-projects-issues]

Gary Russell commented

After further debugging, the issue is we never get a hit on the cache because TypeDescriptor.annotationsMatch() returns false, even though both descriptors have the "same" annotation (but different instances).

[spring-projects-issues]

Juergen Hoeller commented

Gary Russell, could it be that you're not caching the MethodParameter instances that you're repeatedly building a TypeDescriptor for there? We currently assume cached MethodParameter instances for repeated invocations there, since we're actively caching them in all affected places in the core framework.

Of course, we shouldn't have such a regression just because of new MethodParameter instances, and I'm going to look at what we can do there. Apparently Method.getParameterAnnotations() returns fresh annotation instances every time (not caching them like other annotation lookups in the core reflection APIs), failing our identity check.

That said, I nevertheless highly recommend MethodParameter caching in Spring Integration, in particular if Method.getParameterAnnotations() indeed creates fresh annotation instances every time! The annotation creation overhead is worth avoiding there in its own right.

[spring-projects-issues]

Juergen Hoeller commented

Adding a full Annotation.equals check after the identity check in TypeDescriptor.annotationsMatch solves the problem. However, this comes at the price of reflective attribute comparisons even in unique cases if there are several methods with the same number of annotations, so I'm still trying to optimize this.

As per my comment above, all those problems disappear - even cutting down the invocation overhead by a factor of six - when cached MethodParameter objects are passed in.

[spring-projects-issues]

Artem Bilan commented

Juergen,

Thank you for digging this and for the update.
Gary is on PTO this week, although he is on-line from time to time. So, he may provide some feedback eventually.

But let me share my current concerns if that helps.

We don't create MethodParameter instances all the time. We do that only once during initialization to build a SpEL expression based on the method signature. Everything rest is done via SpEL engine at runtime: https://github.com/spring-projects/spring-integration/blob/master/spring-integration-core/src/main/java/org/springframework/integration/util/MessagingMethodInvokerHelper.java#L692

So, I'm not sure that our problem is around MethodParameter...

[spring-projects-issues]

Juergen Hoeller commented

I'm pretty sure that the problem is different Annotation instances for the same method parameters, and that can only really come from repeated Method.getParameterAnnotations() calls, e.g. through repeated MethodParameter creation. In other words, if a shared MethodParameter instance came in for each unique declared parameter, you wouldn't see the cache misses in TypeDescriptor indicated by Gary above.

It's worth debugging this in Spring Integration, finding out about potential repeated MethodParameter instantiation and repeated Method.getParameterAnnotations() calls for repeated invocations of the same handler method. If nothing turns up there, we might indeed have a different problem.

[spring-projects-issues]

Artem Bilan commented

Juergen,

does it say anything to you?

static boolean convertArguments(TypeConverter converter, Object[] arguments, Object methodOrCtor,
			Integer varargsPosition) throws EvaluationException {

	boolean conversionOccurred = false;
	if (varargsPosition == null) {
		for (int i = 0; i < arguments.length; i++) {
			TypeDescriptor targetType = new TypeDescriptor(MethodParameter.forMethodOrConstructor(methodOrCtor, i));
			Object argument = arguments[i];
			arguments[i] = converter.convertValue(argument, TypeDescriptor.forObject(argument), targetType);
			conversionOccurred |= (argument != arguments[i]);
		}
      }
...

That is where I see new MethodParameter in my call stack on each expression.getValue().

[spring-projects-issues]

Gary Russell commented

Juergen Hoeller thanks for looking at this. FYI We have a planned activity to move from SpEL to InvocableHandlerMethod s for this functionality (at least as an - preferred - option), but that is currently planned for 5.0 only because it's a pretty big change.

[spring-projects-issues]

Juergen Hoeller commented

Ok, that clarifies it indeed: You're going through SpEL's generic resolution algorithm there which indeed recreates MethodParameter instances every time... I'll sort this out through an Annotation.equals fallback in TypeDescriptor. So your present approach will work properly again as of Spring Framework 4.3.6.

As a side note, I have no idea why Method.getParameterAnnotations() creates fresh Annotation instances on every call. Annotations on a Method and Constructor itself and also on a Field are cached by the JVM and therefore prepared for identity comparisons. Just parameter-level annotations aren't :-(

[spring-projects-issues]

Juergen Hoeller commented

We check for annotation identity, then same annotation proxy class, then reflective Annotation.equals now. This is efficient enough for shared annotations and covers non-identical but equal parameter annotations as well.

[spring-projects-issues]

Gary Russell commented

Thanks Juergen Hoeller I have confirmed that we are back to 4.3.3 level performance.

[spring-projects-issues]

Mike Noordermeer commented

It seems that this bug causes a massive memory leak for us, with 4.3.5. The convertercache contains millions of elements, taking up 500+MB heap space. Not 100% sure it is this bug, but I will try with 4.3.6 to see if that fixes the issue.

[spring-projects-issues]

Mike Noordermeer commented

I can confirm upgrading to Spring 4.3.6 fixes the problem. For us the problem was not in Spring Integration, but in a @ModelAttribute method using @RequestParam parameters, like this:

    @ModelAttribute
    private void populateModel(@RequestParam(required = false) boolean note1Enabled,
                               @RequestParam(required = false) boolean note2Enabled,
                               @RequestParam(required = false) boolean note3Enabled,
...

This causes a new cache entry for each method execution / parameter. Maybe this is something that needs to be looked into, if the parameter annotations are expected to be cached.