Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ConversionService performance regression [SPR-14929] #19496

Closed
spring-issuemaster opened this issue Nov 21, 2016 · 8 comments

Comments

@spring-issuemaster
Copy link
Collaborator

commented Nov 21, 2016

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
  • #19410 AnnotationFormatterFactory should support @AliasFor
  • #18287 Differentiate between TypeDescriptors with same annotations but different attributes
  • #19388 GenericConversionService.addConverter should be able to determine generic types from target class behind proxy
  • #19493 Improve performance for conversions using a method parameter based type descriptor with annotations
  • #19626 Annotated method argument matching performance issue

0 votes, 7 watchers

@spring-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

commented Nov 21, 2016

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-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

commented Nov 23, 2016

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-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

commented Dec 22, 2016

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-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

commented Dec 22, 2016

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-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

commented Dec 27, 2016

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-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

commented Dec 27, 2016

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-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

commented Dec 27, 2016

Gary Russell commented

See #19626

@spring-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

commented Dec 27, 2016

Juergen Hoeller commented

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
2 participants
You can’t perform that action at this time.