Improve performance for conversions using a method parameter based type descriptor with annotations [SPR-14926]

[spring-projects-issues]

Oliver Drotbohm opened SPR-14926 and commented

When a conversion is invoked using a TypeDescriptor instance that was created for a MethodParameter containing annotations, the lookup of the Converter is significantly slowed down as the TypeDescriptor instances undergo an ….equals(…) check that's quite expensive due to the synthesized annotations.

I wonder whether TypeDescriptor really needs to compare the annotations if the method and the parameter index are well defined as they by definition uniquely identify the parameter.

Here's a sample test case showing the issue:

package org.example.myapi;

import java.lang.reflect.Method;
import java.util.Date;

import org.junit.Test;
import org.springframework.core.MethodParameter;
import org.springframework.core.convert.ConversionService;
import org.springframework.core.convert.TypeDescriptor;
import org.springframework.format.annotation.DateTimeFormat;
import org.springframework.format.annotation.DateTimeFormat.ISO;
import org.springframework.format.support.DefaultFormattingConversionService;
import org.springframework.http.ResponseEntity;
import org.springframework.util.ReflectionUtils;
import org.springframework.web.bind.annotation.RequestParam;

/**
 * @author Oliver Gierke
 */
public class FooTests {

	private static final int ITERATIONS = 1000000;

	private static final ConversionService CONVERSION_SERVICE = new DefaultFormattingConversionService();
	private static final TypeDescriptor STRING_TYPE = TypeDescriptor.valueOf(String.class);

	@Test
	public void methodParameterWithAnnotations() {

		Date date = new Date();

		Method method = ReflectionUtils.findMethod(SomeController.class, "someMethod", Date.class);
		TypeDescriptor sourceDescriptor = TypeDescriptor.nested(new MethodParameter(method, 0), 0);

		long startTime = System.currentTimeMillis();

		for (int i = 0; i < ITERATIONS; i++) {
			CONVERSION_SERVICE.convert(date, sourceDescriptor, STRING_TYPE);
		}

		long duration = (System.currentTimeMillis() - startTime);

		System.out.println("With annotations " + duration);
	}

	@Test
	public void methodParameterWithoutAnnotations() {

		Method method = ReflectionUtils.findMethod(SomeController.class, "someMethod", String.class);
		TypeDescriptor sourceDescriptor = TypeDescriptor.nested(new MethodParameter(method, 0), 0);

		long startTime = System.currentTimeMillis();

		for (int i = 0; i < ITERATIONS; i++) {
			CONVERSION_SERVICE.convert("Foo", sourceDescriptor, STRING_TYPE);
		}

		long duration = (System.currentTimeMillis() - startTime);

		System.out.println("Without annotations " + duration);
	}

	static class SomeController {

		ResponseEntity<Object> someMethod(@RequestParam("foo") @DateTimeFormat(iso = ISO.DATE) Date date) {
			return null;
		}

		ResponseEntity<Object> someMethod(String value) {
			return null;
		}
	}
}

---

Affects: 4.3.4

Reference URL: spring-projects/spring-hateoas#511

Attachments:

• Bildschirmfoto 2016-11-21 um 11.20.48.PNG (154.80 kB)
• Bildschirmfoto 2016-11-26 um 13.16.01.PNG (89.78 kB)
• Bildschirmfoto 2016-11-26 um 13.56.30.PNG (110.74 kB)

Issue Links:

• Spring Performance Optimization, Comparing Classes [SPR-12926] #17519 Spring Performance Optimization, Comparing Classes
• 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
• ConversionService performance regression [SPR-14929] #19496 ConversionService performance regression
• Annotated method argument matching performance issue [SPR-15060] #19626 Annotated method argument matching performance issue
• @DateTimeFormat(iso = ISO.DATE_TIME) should use optimized formatter for LocalDateTime [SPR-14958] #19525 @DateTimeFormat(iso = ISO.DATE_TIME) should use optimized formatter for LocalDateTime

[spring-projects-issues]

Oliver Drotbohm commented

I've attached a screenshot showing the culprit in a test case provided for the original ticket in Spring HATEOAS. Under GenericConversionService.getConverter(…) there's another 35% block for ConcurrentReferenceHashMap.put(…) boiling down to basically the same call path into the equals(…) implementation of TypeDescriptor.

[spring-projects-issues]

Juergen Hoeller commented

This turns out as a different variant of #19496: It's not the annotation comparisons being so expensive per se, it's rather just the merged annotation comparisons that we unnecessarily triggered from TypeDescriptor.equals there as of 4.3.4 due to some unfortunate interaction.

As of 4.3.5, we're comparing the raw declared annotations which seems efficient enough. Being able to isolate the descriptor to type plus annotations seems beneficial still, since for conversion purposes, it doesn't matter which signature the type and the annotations actually came from.

[spring-projects-issues]

Oliver Drotbohm commented

I didn't dive in deeper as I was sort of assuming the "new way" of looking up annotations would always include the synthesization of annotations. Anyway, thanks for the quick turnaround!

[spring-projects-issues]

Oliver Drotbohm commented

I don't see any significant changes in the numbers after the recent fixes . However, it looks like the hotspot has changed to be AnnotationConverterKey.equals(…) again triggering equals(…) method on the proxy (see new screenshot). Looks like the shortcut in TypeDescriptor has caused the code to run into a different but as costly comparison later?

Also, the ticket was marked as fixed in 4.3.5 but I couldn't find a related commit in the 4.3.x branch.

[spring-projects-issues]

Oliver Drotbohm commented

It looks like that AnnotationPrinterConverter.convert(Object, TypeDescriptor, TypeDescriptor) looks up the annotation on the target type, which returns a merged annotation. That merged annotation is then used in AnnotationConverterKey and its equals(…) which in turn then basically causes the same problem as originally described.

[spring-projects-issues]

Oliver Drotbohm commented

I created a local "fix" using the annotation type and the target type descriptor in the cache key instead of the annotation instance (not sure that creates really valid equals comparisons, I just wanted to see where I get if that hotspot is removed. The next thing I run into is the actual conversion. That seems to work well for simple conversions. However, playing around with it, I discovered something quite obscure again:

ResponseEntity<Object> someMethod(@RequestParam("foo") @DateTimeFormat(iso = ISO.DATE) Date date) {…}

Letting the ConversionService convert Date instances into Strings is a lot slower than e.g. Integers. 1 million conversions of Integer instances take ~150ms. For Date formatting, those numbers raise to ~600ms, interestingly with the JodaTime converters involved, which was surprising. If I switch to LocalDateTime instances, those numbers boost up to ~4200ms (see new Screenshot), unfortunately with most of the time spent in the JDK, especially StringBuilder.setLength(). Is that somethign we should bring up with the JDK team?

[spring-projects-issues]

Oliver Drotbohm commented

Looks like the usage of DateTimeFormatter.ISO_DATE (or the constants in general as it also appears with ISO_DATE_TIME, too) is significantly degrading performance. I've created a benchmark to showcase this and pinged Stephen on Twitter to see where this goes.