ConversionService performance regression [SPR-14929]

[spring-projects-issues]

Gary Russell opened SPR-14929 and commented

Consider the following:

public class SpELTests {

	@Test
	public void test() {
		Expression exp = new SpelExpressionParser().parseExpression(
				"#target.filter(headers['dummyHeader'] != null "
				+ "? headers['dummyHeader'] "
				+ ": T(org.springframework.util.Assert).isTrue(false, 'required header not available: dummyHeader'))");
		Message<String> message = MessageBuilder.withPayload("foo").setHeader("dummyHeader", "bar").build();
		EvaluationContext context = new StandardEvaluationContext();
		context.setVariable("target", new DummyFilter());
		StopWatch watch = new StopWatch();
		watch.start();
		for (int i = 0; i < 5000; i++) {
			Object value = exp.getValue(context, message);
		}
		watch.stop();
		System.out.println("Elapsed: " + watch.getTotalTimeSeconds());
	}

	public static class DummyFilter {

		@Filter
		public boolean filter(@Header("dummyHeader") String dummyValue) {
			return true;
		}

	}

}

When run with Spring Framework 4.3.3 it runs in < 0.5 seconds; with 4.3.4 it takes 40+ seconds.

With YourKit, I tracked the problem down to DefaultConversionService.getConverter() with source and target type descriptors:

java.lang.String
@org.springframework.messaging.handler.annotation.Header java.lang.String

The performance issue is because this.converterCache.get(key); seems to miss on every iteration (which in turn causes AnnotationUtils.getDefaultValue() which is where the cost is incurred). getDefaultConverter() correctly returns a NoOp converter which is inserted into the cache but, for some reason, that entry is not found in later iterations.

After several iterations, this.converterCache contains

{ConverterCacheKey [sourceType = java.lang.String, targetType = @org.springframework.messaging.handler.annotation.Header java.lang.String]=NO_OP, 
ConverterCacheKey [sourceType = java.lang.String, targetType = @org.springframework.messaging.handler.annotation.Header java.lang.String]=NO_OP, 
ConverterCacheKey [sourceType = java.lang.String, targetType = java.lang.String]=NO_OP, 
ConverterCacheKey [sourceType = java.lang.String, targetType = @org.springframework.messaging.handler.annotation.Header java.lang.String]=NO_OP, 
ConverterCacheKey [sourceType = java.lang.String, targetType = @org.springframework.messaging.handler.annotation.Header java.lang.String]=NO_OP, 
ConverterCacheKey [sourceType = java.lang.Boolean, targetType = java.lang.Boolean]=NO_OP}

With 4.3.3, I this.converterCache contains:

{ConverterCacheKey [sourceType = java.lang.String, targetType = @org.springframework.messaging.handler.annotation.Header java.lang.String]=NO_OP, 
ConverterCacheKey [sourceType = java.lang.String, targetType = java.lang.String]=NO_OP, 
ConverterCacheKey [sourceType = java.lang.Boolean, targetType = java.lang.Boolean]=NO_OP}

So the issue seems to be the cache entries are not found, perhaps some problem with the hash.

---

Affects: 4.3.4

Issue Links:

• INT-4170 The delivery of message with be much slower to downstream filter with Header parameter
• AnnotationFormatterFactory should support @AliasFor [SPR-14844] #19410 AnnotationFormatterFactory should support @AliasFor
• Differentiate between TypeDescriptors with same annotations but different attributes [SPR-13714] #18287 Differentiate between TypeDescriptors with same annotations but different attributes
• GenericConversionService.addConverter should be able to determine generic types from target class behind proxy [SPR-14822] #19388 GenericConversionService.addConverter should be able to determine generic types from target class behind proxy
• 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
• Annotated method argument matching performance issue [SPR-15060] #19626 Annotated method argument matching performance issue

0 votes, 7 watchers

[spring-projects-issues]

Juergen Hoeller commented

I'm pretty sure this is caused by #19410 since the culprit is the @Header annotation at the parameter level here: Without it, the performance is as fine as with 4.3.3. In other words, the plain presence of that annotation causes the constant cache misses!

[spring-projects-issues]

Juergen Hoeller commented

This turns out to be some really bad interaction between #19410 and #18287: Since the latter forced us to compare actual annotation instances, not just annotation types, and the former brought merged annotation lookups to getAnnotation, equality comparisons all of a sudden triggered the building of merged annotation proxies... all over the place, again and again. Since merged annotations are oh-so-transparent, and since it only affects actually synthesizable annotations (with @AliasFor declarations), we unfortunately haven't noticed this upfront.

In practice, we don't need merged annotations for equality comparisons to begin with. All we need to compare is the raw declared annotations themselves which is efficient enough and brings the performance of annotated parameter lookup very close to regular parameter lookup.

[spring-projects-issues]

Thibault commented

Hi guys,
This issue is still Open for us and the fix failed on the above test and our application which is using @Header in several Spring Integration service activators.

Our biggest concern is that once it gets slower, it never recovers. In our web application exposing a set of API, this translates to slower response times over time.

With the following modified test and this fix, the exp.getValue(context, message) takes about 5ms after 60,000 iterations and increasing while it takes a constant 0-1ms with Spring Framework 4.3.3.

@Test
public void test() {
     Expression exp = new SpelExpressionParser().parseExpression("#target.filter(headers['dummyHeader'] != null "
               + "? headers['dummyHeader'] "
               + ": T(org.springframework.util.Assert).isTrue(false, 'required header not available: dummyHeader'))");
     Message<String> message = MessageBuilder.withPayload("foo").setHeader("dummyHeader", "bar").build();
     EvaluationContext context = new StandardEvaluationContext();
     context.setVariable("target", new DummyFilter());
     StopWatch watch = new StopWatch();
     watch.start();
     for (int i = 0; i < 100000; i++) {
          StopWatch innerwatch = new StopWatch();
          innerwatch.start();
          Object value = exp.getValue(context, message);
          innerwatch.stop();
          System.out.println("Iteration: " + (i + 1) + ',' + innerwatch.getTotalTimeMillis());
     }
     watch.stop();
     System.out.println("Total Elapsed: " + watch.getTotalTimeSeconds());
}
public static class DummyFilter {
     @Filter
     public boolean filter(@Header("dummyHeader") String dummyValue) {
          return true;
     }
}

[spring-projects-issues]

Simon Wong commented

As of SPF v4.3.5, this issue is still not fixed. Please re-open it

Spring v4.3.3
5000 iterations - Elapsed Time 0.4+ secs
10000 iterations - Elapsed Time 0.7+ secs
50000 iterations - Elapsed Time 5+ secs

Spring v4.3.5
5000 iterations - Elapsed Time 1.5+ secs
10000 iterations - Elapsed Time 4+ secs
50000 iterations - Elapsed Time (never ends)

[spring-projects-issues]

Jasper Kremer commented

In several Spring Integration service activators we are using @Header,@Payload annotations.
We are experiencing a considerable performance degradation problem (which gets slower over time, just as Thibault mentioned) with Sprint v4.3.4 an v.4.3.5.

This issue is still Open for us and we hope it will be fixed soon.

[spring-projects-issues]

Artem Bilan commented

Just for clarification:
The fix is included to the Spring Framework 4.3.5 and Spring Integration 4.3.6.
So, be sure, please, that you use exactly this combination of versions.

[spring-projects-issues]

Gary Russell commented

See #19626

[spring-projects-issues]

Juergen Hoeller commented

All, let's continue this thread at #19626. We'll sort this out for 4.3.6, hopefully for good.