Spring Slow prototype bean creation when migrating spring-boot 2.3.5 -> 2.4.1

Affects: Spring Framework 5.3.2

---

I have a project (console based, environment=NONE, only base spring boot starter) with a lot of prototype bean creations at application runtime (not startup), ~15k of beans. I have one interface and near 150 different implemantions of it marked with

@Component
@Primary
@Scope("prototype")

@Configuration has @Bean-method, some kind of object provider, which get bean of concrete class (not interface):

@Configuration
@RequiredArgsConstructor
public class DiagnosticConfiguration {

  private final ApplicationContext applicationContext;

  @Bean
  @Scope("prototype")
  public <T extends BSLDiagnostic> T diagnostic(Class<T> clazz) {
    return applicationContext.getBean(clazz);
  }

}

On spring boot 2.3.5 15000 of diagnostic calls take 12 seconds. On spring boot 2.4.1 - more than 75 seconds. no changes to application code or configs, just dependency bump.

On flame graph I discovered problem (synchonized issue) at CommonAnnotationBeanPostprocessor.findResourceMetadata https://postimg.cc/3ywf5B6Q

Comparison of: 2.3.5: https://postimg.cc/HVdnQYLn 2.4.1: https://postimg.cc/KKw4LtKh

Looks like all bean creations on 2.3.5 took metadata from cache, while all creations at 2.4.1 have "cache miss" and are forced to recreate metadata.

I've asked about this at spring-boot gitter and was redirected here by @wilkinsona.

P.S. I'll try to provide some demo-project, need some time to reproduce it.

Comment From: jhoeller

Could you debug into it and see what causes the cache misses specifically? What kind of cache key is being computed, and how does needsRefresh behave?

Comment From: sbrannen

P.S. I'll try to provide some demo-project, need some time to reproduce it.

Yes, a demo project would be useful.

We are very interested in seeing how your prototype-scoped BSLDiagnostic bean (object provider) is used in practice and what it's being used to achieve.

Comment From: jhoeller

Just noticed that your @Bean method delegates to ApplicationContext.getBean underneath, which is rather unexpected. From a Spring container perspective, this is a central managed bean definition on top of different underlying managed beans. The prototype bean definition will have a constantly changing bean type here, so indeed we might replace the cache entry every time since we don't expect the bean type of a specific bean definition to change all the time.

From that perspective, you might not actually see a 5.2->5.3 regression but rather the effect of a recent fix that got backported to 5.2.x as well: #26019 - but you might not have encountered it in the latest 5.2.x release yet. I'm afraid this fix restores correct behavior; I highly recommend reachitecting your lookup approach to let Spring's container do its per-bean type management.

Comment From: jhoeller

Could you please try Framework 5.2.12 / Boot 2.3.7 as well, confirming that you're seeing the same performance difference there?

In any case, our previous behavior there was clearly broken for changing bean types with new metadata elements to discover, once the first bean type did not expose any metadata elements at all. We could cache metadata for all occurring bean types of the same bean definition but that'd really be against the grain of our bean definition model. I'd rather recommend a custom lookup method that delegates to ApplicationContext.getBean, with that lookup method not being marked as a managed bean definition itself (given that there is nothing for the container to manage, just unnecessary metadata discovery overhead).

Comment From: wylgithub

very nice demo！

Comment From: nixel2007

@sbrannen

We are very interested in seeing how your prototype-scoped BSLDiagnostic bean (object provider) is used in practice and what it's being used to achieve.

I can link real project :)

repo - https://github.com/1c-syntax/bsl-language-server, some docs in english - https://1c-syntax.github.io/bsl-language-server/en)

It is a Language Server Protocol implementation for 1C:Enterprise Platform internal language. One of its components is a static alanysis tool, implemented via "diagnostics" ("inspections" in terms of IntelliJ IDEA)

All diagnostics implements base interface BSLDiagnostic - https://github.com/1c-syntax/bsl-language-server/blob/develop/src/main/java/com/github/_1c_syntax/bsl/languageserver/diagnostics/BSLDiagnostic.java and annotated with DiagnosticMetadata (https://github.com/1c-syntax/bsl-language-server/blob/develop/src/main/java/com/github/_1c_syntax/bsl/languageserver/diagnostics/metadata/DiagnosticMetadata.java) which marks them as @Component

For example: https://github.com/1c-syntax/bsl-language-server/blob/develop/src/main/java/com/github/_1c_syntax/bsl/languageserver/diagnostics/CompilationDirectiveLostDiagnostic.java

DiagnosticConfiguration is located here https://github.com/1c-syntax/bsl-language-server/blob/develop/src/main/java/com/github/_1c_syntax/bsl/languageserver/diagnostics/infrastructure/DiagnosticConfiguration.java

It is called from DiagnosticsConfiguration (see s in DiagnosticS) - https://github.com/1c-syntax/bsl-language-server/blob/develop/src/main/java/com/github/_1c_syntax/bsl/languageserver/diagnostics/infrastructure/DiagnosticsConfiguration.java

Main goal of DiagnosticsConfiguration (with s) is to create set of BSLDiagnostic interface implemantaion instances for "DocumentContext" - object (prototype bean also) that represents data of each text document in workspace. Diagnostic are filtred by several conditions - https://github.com/1c-syntax/bsl-language-server/blob/89c5cc2bcd97e56007d88c5d87a02d65277fb163/src/main/java/com/github/_1c_syntax/bsl/languageserver/diagnostics/infrastructure/DiagnosticsConfiguration.java#L75-L82

These conditions depend on data in DocumentContext, so every DocumentContext gets it's own list of BSLDiagnostic implementation types which are then instantiated via DiagnosticConfiguration (w/o s).

sorry if my explanations seem confusing :(

Comment From: nixel2007

@jhoeller

What kind of cache key is being computed

key is a bean string identifier (camel-cased class name)

Comment From: nixel2007

@jhoeller

Could you please try Framework 5.2.12 / Boot 2.3.7 as well, confirming that you're seeing the same performance difference there?

yes, I see the same regression on Boot 2.3.7.

Comment From: nixel2007

I'd rather recommend a custom lookup method that delegates to ApplicationContext.getBean, with that lookup method not being marked as a managed bean definition itself (given that there is nothing for the container to manage, just unnecessary metadata discovery overhead).

oh yes, it works! I've removed @Bean from diagnostic method and flame graph looks normal now.

Thank you so much! problem is solved and issue can be closed. May be https://github.com/spring-projects/spring-framework/commit/10bff054a9c60d935be5ec854d71b1af9452b928 deserves some mention in changelog, migration guide or logs.

Comment From: jhoeller

Thanks for the quick turnaround, good to hear that it works for you now!

I've added a corresponding note to https://github.com/spring-projects/spring-framework/wiki/Upgrading-to-Spring-Framework-5.x

Comment From: wtfiwtz

I had a cyclic dependency error on some bean loading after spring-beans went from 5.2.10 to 5.2.11 and above, which seems to be related to this regression fix.

To resolve it I had to add some @Lazy annotations as per this webpage: https://howtodoinjava.com/spring5/core/spring-bean-eager-vs-lazy-init/

I could then get up to date (spring boot 2.4.3 and spring-framework 5.4.3 releases)

Sample error was:

Error starting ApplicationContext. To display the conditions report re-run your application with 'debug' enabled.
2021-02-11 09:20:20,293 [ERROR] org.springframework.boot.SpringApplication - Application run failed
org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'ListenerBean': Unsatisfied depend
ency expressed through field 'mXYZService'; nested exception is org.springframework.beans.factory.UnsatisfiedDependencyExceptio
n: Error creating bean with name 'XYZServiceImpl': Unsatisfied dependency expressed through field 'mXYZService'; nested
exception is org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'paymentBizServiceImpl': Unsati
sfied dependency expressed through field 'mABCService'; nested exception is org.springframework.beans.factory.BeanCurrentl
yInCreationException: Error creating bean with name 'ABCServiceImpl': Bean with name 'ABCServiceImpl' ha
s been injected into other beans [DEFRestTemplate] in its raw version as part of a circular reference, but has eventually been
 wrapped. This means that said other beans do not use the final version of the bean. This is often the result of over-eager type matching -
consider using 'getBeanNamesForType' with the 'allowEagerInit' flag turned off, for example.
        at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor$AutowiredFieldElement.inject(AutowiredAnnotatio
nBeanPostProcessor.java:643)
        at org.springframework.beans.factory.annotation.InjectionMetadata.inject(InjectionMetadata.java:119)
        at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor.postProcessProperties(AutowiredAnnotationBeanPo
stProcessor.java:399)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.populateBean(AbstractAutowireCapableBeanFactory.java
:1415)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java
:608)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:5
31)
        at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:335)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234)
        at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:333)

Cheers, Nigel