Longer Startup Times Post Spring-Boot 3.4.0 Upgrade

[carolmorneau]

We noticed longer startup times after upgrading to Spring-Boot 3.4.0 and Spring Cloud Stream 4.2.0.

Spring-Boot 3.3.8 & Spring Cloud Stream 4.1.4

2025-02-05T09:55:47.778-05:00  INFO 37245 --- [  restartedMain] o.s.c.s.binder.DefaultBinderFactory      : Creating binder: undefined
2025-02-05T09:55:47.779-05:00  INFO 37245 --- [  restartedMain] o.s.c.s.binder.DefaultBinderFactory      : Constructing binder child context for undefined
2025-02-05T09:55:47.789-05:00 DEBUG 37245 --- [  restartedMain] c.s.c.c.e.l.BinderEventPropagator        : Publishing event com.solace.connector.core.event.BinderContextInitializedEvent[binderName=undefined, source=undefined_context, started on Wed Feb 05 09:55:47 EST 2025, parent: org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@14f807c3]
2025-02-05T09:55:47.789-05:00 TRACE 37245 --- [  restartedMain] c.s.c.c.e.listener.StartupEventListener  : Received binder context initialized event for binder: undefined
2025-02-05T09:55:47.789-05:00  INFO 37245 --- [  restartedMain] o.s.c.s.binder.DefaultBinderFactory      : Caching the binder: undefined

Spring-Boot 3.4.0 & Spring Cloud Stream 4.2.0

2025-02-05T09:37:10.626-05:00  INFO 34207 --- [  restartedMain] o.s.c.s.binder.DefaultBinderFactory      : Creating binder: undefined
2025-02-05T09:37:10.626-05:00  INFO 34207 --- [  restartedMain] o.s.c.s.binder.DefaultBinderFactory      : Constructing binder child context for undefined
2025-02-05T09:37:11.218-05:00 DEBUG 34207 --- [  restartedMain] c.s.c.c.e.l.BinderEventPropagator        : Publishing event com.solace.connector.core.event.BinderContextInitializedEvent[binderName=undefined, source=undefined_context, started on Wed Feb 05 09:37:10 EST 2025, parent: org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@7f447734]
2025-02-05T09:37:11.218-05:00 TRACE 34207 --- [  restartedMain] c.s.c.c.e.listener.StartupEventListener  : Received binder context initialized event for binder: undefined
2025-02-05T09:37:11.218-05:00  INFO 34207 --- [  restartedMain] o.s.c.s.binder.DefaultBinderFactory      : Caching the binder: undefined

Note the difference for Constructing binder child context for undefined of >500ms.

Note that the undefined binder is a dummy binder that does nothing. Therefore, there is no connection related costs in the above.

Spring-Boot Change

We have identified the specific Spring Boot commit responsible for the slower startup times.

Slower Spring Cloud Stream Operations

We also identified which operations have become more expansive.

1. This binderProducingContext.refresh() has become significantly more expensive.
2. Also, we have initialization logic which makes multiple calls to bindingServiceProperties.getBinder(binding) and have observed that when the binding is a producer binding, the getBinder() call takes ~4ms instead of 0ms. Calling getBinder(binding) on a consumer binding is still fast and takes 0ms.

Summary

A recent Spring-Boot change to child/parent contexts slows down startup. Can you tell how the change may be affecting Spring Cloud Stream?

[olegz]

@carolmorneau Can you please give it a shot with 4.2.1-SNAPSHOT and let me know. I expect it to actually be faster now

[olegz]

@Mrc0113 ^^

[carolmorneau]

Hi @olegz, unfortunately, I do not see improvements with 4.2.1-SNAPSHOT. I see same performance as 4.2.0.

From my testing, the slowdown was introduced with this commit. Can you think of any effect this could have had on Spring Cloud Stream?

[olegz]

@carolmorneau email me when you are online so we can zoom and do some screen share. It is strange as I see different results and in fact see that it is now faster

[carolmorneau]

Hi @olegz , following our chat, I've retested with Spring Boot 3.3.9 and Spring Cloud Stream 4.1.5 and I can see that, with these versions, calling bindingServiceProperties.getBinder(binding) does not trigger the bindToDefault() path.

However, post upgrade, calls to bindingServiceProperties.getBinder(binding) which correspond to a producer binding do trigger the bindToDefault() path (takes an extra ~4ms per call).

I should have likely mentioned this when I opened the issue but here's how the output bindings are defined:

spring:
  cloud:
    config:
      # [INTERNAL]  Pre-create output bindings
      output-bindings: "\
        output-0;\
        output-1;\
        output-2;\
        output-3;\
        output-4;\
        output-5;\
        output-6;\
        output-7;\
        output-8;\
        output-9;\
        output-10;\
        output-11;\
        output-12;\
        output-13;\
        output-14;\
        output-15;\
        output-16;\
        output-17;\
        output-18;\
        output-19"

      default-binder: undefined

[olegz]

@carolmorneau I just noticed something. What is

spring:
  cloud:
    config:
      output-bindings: 

???

We don't have this property. It supposed to be

spring:
  cloud:
    stream:
      output-bindings: 

Basically with config nothing is precreated as stream doesn't know anything about it so the first call to getBinder calls bindToDefault

I observe the same behavior with previous version, as it also does not recognise config

Could it be something Solace related?

I also see the performance improvement with boot 3.4.*.

[carolmorneau]

My apologies, that was supposed to say:

spring:
  cloud:
    stream:
      output-bindings: 

Today, we have made optimizations on our end which brings down the initialization of our undefined binder to ~230ms from ~550ms.

This optimization combined with the optimization that you've done on your end help.

This is slower than the ~10ms that we were seeing pre Spring-Boot upgrade but we'll need to narrow it down some more before we can make real progress. We'll open a new issue, likely against Spring-Boot, when we have it narrowed down.

Thank you for looking into this issue. It can be closed.