dev mode Startup time regression between 2.2.3.Final and 2.5.0.CR1

[Postremus]

Describe the bug

I just migrated from 2.2.3.Final to 2.4.2.Final.
Noticed that my project is starting a bit slower in dev mode.
I also cross checked against 1.13.1.Final, which was a bit faster still than 2.2.

For the reproducer project, I get following dev mode startup times on my machine:

2.5.0.CR1: 2.493s
2.2.3.Final: 2.273s
1.13.1.Final: 2.059s

Flamegraphs:
flamegraphs.zip

Output when running with -Dquarkus.debug.print-startup-times=true

1.13.1.Final (Click to expand)

[INFO] --- quarkus-maven-plugin:1.13.1.Final:dev (default-cli) @ profiling ---
Listening for transport dt_socket at address: 5005
2021-11-19 21:30:00,424 WARN  [io.qua.agr.dep.AgroalProcessor] (build-32) The Agroal dependency is present but no JDBC datasources have
 been defined.
2021-11-19 21:30:00,456 WARN  [io.qua.dat.dep.dev.DevServicesDatasourceProcessor] (build-52) Unable to determine a database type for de
fault datasource
Build step SmallRyeOpenApiProcessor.classLoaderHack completed in: 10ms
Build step MutinyProcessor.configureDroppedExceptionHandlerAndThreadBlockingChecker completed in: 21ms
Build step LoggingResourceProcessor.setupLoggingStaticInit completed in: 1ms
Build step ResteasyReactiveDevModeProcessor.addReactiveRoutesExceptionMapper completed in: 2ms
Build step ResteasyReactiveDevModeProcessor.setupExceptionMapper completed in: 0ms
Build step ArcDevProcessor.invocationsEndpoint completed in: 1ms
Build step ArcDevProcessor.eventsEndpoint completed in: 0ms
Build step VertxCoreProcessor.ioThreadDetector completed in: 2ms
Build step DevConsoleProcessor.handler completed in: 1ms
Build step DevConsoleProcessor.invokeEndpoint completed in: 0ms
Build step BlockingOperationControlBuildStep.blockingOP completed in: 0ms
Build step SmallRyeHealthProcessor.build completed in: 0ms
Build step SmallRyeContextPropagationProcessor.buildStatic completed in: 1ms
Build step NativeImageConfigBuildStep.build completed in: 0ms
Build step ResteasyReactiveDevModeProcessor.addStaticResourcesExceptionMapper completed in: 0ms
Build step JacksonProcessor.pushConfigurationBean completed in: 1ms
Build step CacheProcessor.configureCacheManagerSyntheticBean completed in: 0ms
Build step StaticResourcesProcessor.staticInit completed in: 0ms
Build step HibernateValidatorProcessor.build completed in: 2ms
Build step SyntheticBeansProcessor.initStatic completed in: 0ms
Build step ArcProcessor.generateResources completed in: 170ms
Build step SmallRyeMetricsProcessor.build completed in: 6ms
Build step SmallRyeMetricsProcessor.createRoute completed in: 1ms
Build step ResteasyReactiveProcessor.setupEndpoints completed in: 31ms
Build step ResteasyReactiveDevModeProcessor.addAdditionalEndpointsExceptionMapper completed in: 1ms
Build step BootstrapConfigSetupBuildStep.setupBootstrapConfig completed in: 0ms
Build step NettyProcessor.eagerlyInitClass completed in: 0ms
Build step RuntimeConfigSetupBuildStep.setupRuntimeConfig completed in: 16ms
Build step SmallRyeMetricsProcessor.dropRegistriesAtShutdown completed in: 0ms
Build step SmallRyeMetricsProcessor.registerBaseAndVendorMetrics completed in: 12ms
Build step VertxCoreProcessor.eventLoopCount completed in: 1ms
Build step VertxCoreProcessor.build completed in: 0ms
Build step VertxHttpProcessor.cors completed in: 1ms
Build step HttpSecurityProcessor.initBasicAuth completed in: 0ms
Build step ThreadPoolSetup.createExecutor completed in: 8ms
Build step MutinyProcessor.initExecutor completed in: 0ms
Build step ArcProcessor.setupExecutor completed in: 1ms
Build step SmallRyeContextPropagationProcessor.build completed in: 0ms
Build step BannerProcessor.recordBanner completed in: 1ms
Build step SmallRyeOpenApiProcessor.handler completed in: 0ms
Build step SmallRyeHealthProcessor.registerHealthUiHandler completed in: 1ms
Build step ArcDevProcessor.registerRoutes completed in: 0ms
Build step VertxHttpProcessor.bodyHandler completed in: 2ms
Build step SwaggerUiProcessor.registerSwaggerUiHandler completed in: 0ms
__  ____  __  _____   ___  __ ____  ______
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/
2021-11-19 21:30:01,660 WARN  [io.qua.config] (Quarkus Main Thread) Unrecognized configuration key "quarkus.debug.print-startup-times"
was provided; it will be ignored; verify that the dependency extension for this configuration is set or that you did not make a typo
2021-11-19 21:30:01,927 WARN  [io.qua.config] (Quarkus Main Thread) Unrecognized configuration key "quarkus.debug.print-startup-times"
was provided; it will be ignored; verify that the dependency extension for this configuration is set or that you did not make a typo
Build step LoggingResourceProcessor.setupLoggingRuntimeInit completed in: 6ms
Build step ConfigGenerationBuildStep.checkForBuildTimeConfigChange completed in: 3ms
Build step NarayanaJtaProcessor.build completed in: 7ms
Build step DevConsoleProcessor.setupDevConsoleRoutes completed in: 5ms
Build step ConfigBuildStep.registerConfigMappings completed in: 1ms
Build step SyntheticBeansProcessor.initRuntime completed in: 0ms
Build step StaticResourcesProcessor.runtimeInit completed in: 3ms
Build step ConfigBuildStep.validateConfigProperties completed in: 0ms
Build step ResteasyReactiveProcessor.applyRuntimeConfig completed in: 0ms
Build step VertxHttpProcessor.initializeRouter completed in: 81ms
Build step VertxHttpProcessor.finalizeRouter completed in: 5ms
Build step ShutdownListenerBuildStep.setupShutdown completed in: 0ms
Build step DevConsoleProcessor.runtimeTemplates completed in: 10ms
Build step LifecycleEventsBuildStep.startupEvent completed in: 1ms
Build step VertxHttpProcessor.openSocket completed in: 70ms
2021-11-19 21:30:02,149 INFO  [io.quarkus] (Quarkus Main Thread) profiling 1.0.0-SNAPSHOT on JVM (powered by Quarkus 1.13.1.Final) star
ted in 2.205s. Listening on: http://localhost:8080
2021-11-19 21:30:02,149 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2021-11-19 21:30:02,150 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [agroal, cache, cdi, hibernate-validator, mutiny,
narayana-jta, resteasy-reactive, resteasy-reactive-jackson, smallrye-context-propagation, smallrye-health, smallrye-metrics, smallrye-o
penapi, swagger-ui]

2.2.3.Final (Click to expand)

 [INFO] --- quarkus-maven-plugin:2.2.3.Final:dev (default-cli) @ profiling ---
[INFO] Invoking org.apache.maven.plugins:maven-resources-plugin:2.6:testResources @ profiling
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory C:\Users\Martin\IdeaProjects\profiling\src\test\resources
[INFO] Invoking org.apache.maven.plugins:maven-compiler-plugin:3.8.1:testCompile @ profiling
[INFO] No sources to compile
Listening for transport dt_socket at address: 5005
2021-11-19 21:32:42,166 WARN  [io.qua.agr.dep.AgroalProcessor] (build-31) The Agroal dependency is present but no JDBC datasources have
 been defined.
2021-11-19 21:32:42,186 WARN  [io.qua.dat.dep.dev.DevServicesDatasourceProcessor] (build-11) Unable to determine a database type for de
fault datasource
Build step LoggingResourceProcessor.setupLoggingStaticInit completed in: 1ms
Build step ResteasyReactiveDevModeProcessor.addReactiveRoutesExceptionMapper completed in: 1ms
Build step SmallRyeOpenApiProcessor.classLoaderHack completed in: 13ms
Build step MutinyProcessor.buildTimeInit completed in: 5ms
Build step ResteasyReactiveDevModeProcessor.setupExceptionMapper completed in: 0ms
Build step ArcDevProcessor.invocationsEndpoint completed in: 0ms
Build step ArcDevProcessor.eventsEndpoint completed in: 0ms
Build step CacheDevConsoleProcessor.invokeEndpoint completed in: 0ms
Build step VertxCoreProcessor.ioThreadDetector completed in: 2ms
Build step DevUIDatasourceProcessor.devConsoleCleanDatabaseHandler completed in: 0ms
Build step AgroalProcessor.addHealthCheck completed in: 1ms
Build step DevConsoleProcessor.handler completed in: 2ms
Build step BlockingOperationControlBuildStep.blockingOP completed in: 0ms
Build step SmallRyeHealthProcessor.build completed in: 1ms
Build step SmallRyeContextPropagationProcessor.buildStatic completed in: 2ms
Build step NativeImageConfigBuildStep.build completed in: 0ms
Build step JacksonProcessor.pushConfigurationBean completed in: 1ms
Build step ResteasyReactiveDevModeProcessor.addStaticResourcesExceptionMapper completed in: 0ms
Build step CacheProcessor.configureCacheManagerSyntheticBean completed in: 0ms
Build step StaticResourcesProcessor.staticInit completed in: 1ms
Build step HibernateValidatorProcessor.build completed in: 1ms
Build step SyntheticBeansProcessor.initStatic completed in: 1ms
Build step ArcProcessor.generateResources completed in: 136ms
Build step SmallRyeMetricsProcessor.build completed in: 6ms
Build step SmallRyeMetricsProcessor.createRoute completed in: 1ms
Build step ResteasyReactiveProcessor.setupEndpoints completed in: 38ms
Build step ResteasyReactiveDevModeProcessor.addAdditionalEndpointsExceptionMapper completed in: 0ms
Build step BootstrapConfigSetupBuildStep.setupBootstrapConfig completed in: 0ms
Build step RuntimeConfigSetupBuildStep.setupRuntimeConfig completed in: 17ms
Build step NettyProcessor.eagerlyInitClass completed in: 0ms
Build step SmallRyeMetricsProcessor.dropRegistriesAtShutdown completed in: 1ms
Build step SmallRyeMetricsProcessor.registerBaseAndVendorMetrics completed in: 7ms
Build step VertxCoreProcessor.eventLoopCount completed in: 0ms
Build step VertxCoreProcessor.createVertxThreadFactory completed in: 0ms
Build step VertxCoreProcessor.createVertxContextHandlers completed in: 0ms
Build step VertxHttpProcessor.cors completed in: 0ms
Build step HttpSecurityProcessor.initBasicAuth completed in: 1ms
Build step ThreadPoolSetup.createExecutor completed in: 7ms
Build step MutinyProcessor.runtimeInit completed in: 0ms
Build step ArcProcessor.setupExecutor completed in: 0ms
Build step BannerProcessor.recordBanner completed in: 0ms
Build step SmallRyeOpenApiProcessor.handler completed in: 7ms
Build step SmallRyeHealthProcessor.registerHealthUiHandler completed in: 0ms
Build step TestsProcessor.setupTestRoutes completed in: 2ms
Build step SmallRyeContextPropagationProcessor.build completed in: 3ms
Build step ArcDevProcessor.registerRoutes completed in: 1ms
Build step VertxCoreProcessor.build completed in: 1ms
Build step SwaggerUiProcessor.registerSwaggerUiHandler completed in: 0ms
Build step VertxHttpProcessor.bodyHandler completed in: 2ms
Build step NarayanaJtaProcessor.build completed in: 14ms
Build step ConfigBuildStep.registerConfigClasses completed in: 1ms
__  ____  __  _____   ___  __ ____  ______
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/
2021-11-19 21:32:43,503 WARN  [io.qua.config] (Quarkus Main Thread) Unrecognized configuration key "quarkus.debug.print-startup-times"
was provided; it will be ignored; verify that the dependency extension for this configuration is set or that you did not make a typo
Build step LoggingResourceProcessor.setupLoggingRuntimeInit completed in: 5ms
Build step ConfigGenerationBuildStep.checkForBuildTimeConfigChange completed in: 3ms
Build step DevConsoleProcessor.setupDevConsoleRoutes completed in: 0ms
Build step SyntheticBeansProcessor.initRuntime completed in: 1ms
Build step ConfigBuildStep.validateConfigProperties completed in: 1ms
Build step StaticResourcesProcessor.runtimeInit completed in: 5ms
Build step VertxHttpProcessor.initializeRouter completed in: 82ms
Build step ResteasyReactiveProcessor.applyRuntimeConfig completed in: 0ms
Build step VertxHttpProcessor.finalizeRouter completed in: 5ms
Build step ShutdownListenerBuildStep.setupShutdown completed in: 1ms
Build step DevConsoleProcessor.runtimeTemplates completed in: 12ms
Build step LifecycleEventsBuildStep.startupEvent completed in: 1ms
Build step VertxHttpProcessor.openSocket completed in: 89ms
2021-11-19 21:32:44,010 INFO  [io.quarkus] (Quarkus Main Thread) profiling 1.0.0-SNAPSHOT on JVM (powered by Quarkus 2.2.3.Final) start
ed in 2.382s. Listening on: http://localhost:8080
2021-11-19 21:32:44,012 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2021-11-19 21:32:44,012 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [agroal, cache, cdi, hibernate-validator, narayana
-jta, resteasy-reactive, resteasy-reactive-jackson, smallrye-context-propagation, smallrye-health, smallrye-metrics, smallrye-openapi,
swagger-ui]

2.5.0.CR1(Click to expand)

[INFO] --- quarkus-maven-plugin:2.5.0.CR1:dev (default-cli) @ profiling ---
[INFO] Invoking org.apache.maven.plugins:maven-resources-plugin:2.6:testResources) @ profiling
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory C:\Users\Martin\IdeaProjects\profiling\src\test\resources
[INFO] Invoking org.apache.maven.plugins:maven-compiler-plugin:3.8.1:testCompile) @ profiling
[INFO] No sources to compile
Listening for transport dt_socket at address: 5005
2021-11-19 21:33:27,275 WARN  [io.qua.agr.dep.AgroalProcessor] (build-47) The Agroal dependency is present but no JDBC datasources have
 been defined.
2021-11-19 21:33:27,812 WARN  [io.qua.dat.dep.dev.DevServicesDatasourceProcessor] (build-62) Unable to determine a database type for de
fault datasource
2021-11-19 21:33:28,751 Build step NioThreadPoolDevModeProcessor.setupTCCL completed in: 0ms
2021-11-19 21:33:28,756 Build step ResteasyReactiveDevModeProcessor.addReactiveRoutesExceptionMapper completed in: 1ms
2021-11-19 21:33:28,772 Build step SmallRyeOpenApiProcessor.classLoaderHack completed in: 14ms
2021-11-19 21:33:28,776 Build step LoggingResourceProcessor.setupLoggingStaticInit completed in: 1ms
2021-11-19 21:33:28,783 Build step MutinyProcessor.buildTimeInit completed in: 5ms
2021-11-19 21:33:28,786 Build step ResteasyReactiveDevModeProcessor.setupExceptionMapper completed in: 0ms
2021-11-19 21:33:28,789 Build step DataSourcesExcludedFromHealthChecksProcessor.produceBean completed in: 0ms
2021-11-19 21:33:28,791 Build step ArcDevProcessor.eventsEndpoint completed in: 0ms
2021-11-19 21:33:28,794 Build step DevUIDatasourceProcessor.devConsoleCleanDatabaseHandler completed in: 0ms
2021-11-19 21:33:28,796 Build step CacheDevConsoleProcessor.invokeEndpoint completed in: 0ms
2021-11-19 21:33:28,800 Build step VertxCoreProcessor.ioThreadDetector completed in: 2ms
2021-11-19 21:33:28,803 Build step ArcDevProcessor.invocationsEndpoint completed in: 0ms
2021-11-19 21:33:28,806 Build step DevConsoleProcessor.handler completed in: 1ms
2021-11-19 21:33:28,808 Build step BlockingOperationControlBuildStep.blockingOP completed in: 0ms
2021-11-19 21:33:28,812 Build step SmallRyeContextPropagationProcessor.buildStatic completed in: 2ms
2021-11-19 21:33:28,815 Build step SmallRyeHealthProcessor.build completed in: 0ms
2021-11-19 21:33:28,818 Build step NativeImageConfigBuildStep.build completed in: 0ms
2021-11-19 21:33:28,820 Build step ResteasyReactiveDevModeProcessor.addStaticResourcesExceptionMapper completed in: 0ms
2021-11-19 21:33:28,823 Build step CacheProcessor.configureCacheManagerSyntheticBean completed in: 0ms
2021-11-19 21:33:28,825 Build step HibernateValidatorProcessor.build completed in: 0ms
2021-11-19 21:33:28,828 Build step SyntheticBeansProcessor.initStatic completed in: 0ms
2021-11-19 21:33:28,948 Build step ArcProcessor.generateResources completed in: 118ms
2021-11-19 21:33:28,958 Build step SmallRyeMetricsProcessor.build completed in: 6ms
2021-11-19 21:33:28,961 Build step SmallRyeMetricsProcessor.createRoute completed in: 1ms
2021-11-19 21:33:28,964 Build step ResteasyReactiveProcessor.setupEndpoints completed in: 1ms
2021-11-19 21:33:28,974 Build step ResteasyReactiveProcessor.serverSerializers completed in: 9ms
2021-11-19 21:33:29,007 Build step ResteasyReactiveProcessor.setupDeployment completed in: 31ms
2021-11-19 21:33:29,009 Build step ResteasyReactiveDevModeProcessor.addAdditionalEndpointsExceptionMapper completed in: 0ms
2021-11-19 21:33:29,012 Build step BootstrapConfigSetupBuildStep.setupBootstrapConfig completed in: 0ms
2021-11-19 21:33:29,033 Build step RuntimeConfigSetupBuildStep.setupRuntimeConfig completed in: 19ms
2021-11-19 21:33:29,035 Build step NettyProcessor.eagerlyInitClass completed in: 0ms
2021-11-19 21:33:29,037 Build step SmallRyeMetricsProcessor.dropRegistriesAtShutdown completed in: 0ms
2021-11-19 21:33:29,046 Build step SmallRyeMetricsProcessor.registerBaseAndVendorMetrics completed in: 7ms
2021-11-19 21:33:29,048 Build step VertxCoreProcessor.createVertxContextHandlers completed in: 0ms
2021-11-19 21:33:29,050 Build step VertxCoreProcessor.createVertxThreadFactory completed in: 0ms
2021-11-19 21:33:29,052 Build step VertxHttpProcessor.cors completed in: 0ms
2021-11-19 21:33:29,053 Build step VertxCoreProcessor.eventLoopCount completed in: 0ms
2021-11-19 21:33:29,056 Build step HttpSecurityProcessor.initBasicAuth completed in: 0ms
2021-11-19 21:33:29,064 Build step ThreadPoolSetup.createExecutor completed in: 6ms
2021-11-19 21:33:29,067 Build step MutinyProcessor.runtimeInit completed in: 0ms
2021-11-19 21:33:29,068 Build step ArcProcessor.setupExecutor completed in: 0ms
2021-11-19 21:33:29,074 Build step TestsProcessor.setupTestRoutes completed in: 3ms
2021-11-19 21:33:29,076 Build step SmallRyeHealthProcessor.registerHealthUiHandler completed in: 0ms
2021-11-19 21:33:29,078 Build step ArcDevProcessor.registerRoutes completed in: 0ms
2021-11-19 21:33:29,084 Build step SmallRyeContextPropagationProcessor.build completed in: 3ms
2021-11-19 21:33:29,087 Build step VertxCoreProcessor.build completed in: 0ms
2021-11-19 21:33:29,088 Build step BannerProcessor.recordBanner completed in: 0ms
2021-11-19 21:33:29,093 Build step VertxHttpProcessor.bodyHandler completed in: 2ms
2021-11-19 21:33:29,175 Build step VertxHttpProcessor.preinitializeRouter completed in: 81ms
2021-11-19 21:33:29,191 Build step NarayanaJtaProcessor.build completed in: 13ms
__  ____  __  _____   ___  __ ____  ______
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/
2021-11-19 21:33:28,750 WARN  [io.qua.config] (Quarkus Main Thread) Unrecognized configuration key "quarkus.debug.print-startup-times"
was provided; it will be ignored; verify that the dependency extension for this configuration is set or that you did not make a typo
2021-11-19 21:33:29,197 Build step LoggingResourceProcessor.setupLoggingRuntimeInit completed in: 4ms
2021-11-19 21:33:29,202 Build step ConfigGenerationBuildStep.checkForBuildTimeConfigChange completed in: 3ms
2021-11-19 21:33:29,212 Build step SmallRyeOpenApiProcessor.handler completed in: 7ms
2021-11-19 21:33:29,214 Build step SwaggerUiProcessor.registerSwaggerUiHandler completed in: 0ms
2021-11-19 21:33:29,216 Build step DevConsoleProcessor.setupDevConsoleRoutes completed in: 0ms
2021-11-19 21:33:29,218 Build step SyntheticBeansProcessor.initRuntime completed in: 0ms
2021-11-19 21:33:29,221 Build step VertxProcessor.build completed in: 0ms
2021-11-19 21:33:29,223 Build step ConfigBuildStep.registerConfigClasses completed in: 0ms
2021-11-19 21:33:29,226 Build step ConfigBuildStep.validateConfigValues completed in: 1ms
2021-11-19 21:33:29,233 Build step StaticResourcesProcessor.runtimeInit completed in: 5ms
2021-11-19 21:33:29,235 Build step ResteasyReactiveProcessor.applyRuntimeConfig completed in: 0ms
2021-11-19 21:33:29,240 Build step VertxHttpProcessor.initializeRouter completed in: 3ms
2021-11-19 21:33:29,246 Build step VertxHttpProcessor.finalizeRouter completed in: 4ms
2021-11-19 21:33:29,248 Build step ShutdownListenerBuildStep.setupShutdown completed in: 0ms
2021-11-19 21:33:29,262 Build step DevConsoleProcessor.runtimeTemplates completed in: 12ms
2021-11-19 21:33:29,264 Build step LifecycleEventsBuildStep.startupEvent completed in: 0ms
2021-11-19 21:33:29,353 Build step VertxHttpProcessor.openSocket completed in: 86ms
2021-11-19 21:33:29,355 INFO  [io.quarkus] (Quarkus Main Thread) profiling 1.0.0-SNAPSHOT on JVM (powered by Quarkus 2.5.0.CR1) started
 in 2.712s. Listening on: http://localhost:8080
2021-11-19 21:33:29,356 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2021-11-19 21:33:29,357 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [agroal, cache, cdi, hibernate-validator, narayana
-jta, resteasy-reactive, resteasy-reactive-jackson, smallrye-context-propagation, smallrye-health, smallrye-metrics, smallrye-openapi,
swagger-ui, vertx]

Expected behavior

No response

Actual behavior

No response

How to Reproduce?

Download the reproducer:
profiling.zip

1. Execute mvnw clean compile quarkus:dev, against quarkus 1.13.1.Final, 2.2.3.Final, and 2.5.1.CR1. Take note of the time reported in the "started in xxx" line.

Output of uname -a or ver

Microsoft Windows [Version 10.0.19043.1348]

Output of java -version

openjdk 17 2021-09-14 OpenJDK Runtime Environment Temurin-17+35 (build 17+35) OpenJDK 64-Bit Server VM Temurin-17+35 (build 17+35, mixed mode, sharing)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

No response

Build tool (ie. output of mvnw --version or gradlew --version)

Apache Maven 3.6.3 (cecedd343002696d0abb50b32b541b8a6ba2883f) Maven home: C:\Users\Martin.m2\wrapper\dists\apache-maven-3.6.3-bin\1iopthnavndlasol9gbrbg6bf2\apache-maven-3.6.3 Java version: 17, vendor: Eclipse Adoptium, runtime: C:\tools\java\17 Default locale: de_DE, platform encoding: Cp1252 OS name: "windows 10", version: "10.0", arch: "amd64", family: "windows"

Additional information

No response

[famod]

Can you check again with -Dquarkus.debug.print-startup-times=true? This might show the build step that's now slower.

PS: Although I have to say this might not even be casued by increased build step runtimes, but we'll see.

[Postremus]

Output of -Dquarkus.debug.print-startup-times=true is added to the starting post. On first glance, I see no obvious culprit for the increased startup time.

[Postremus]

I created some jfr recordings, and converted them to flamegraphs for easier viewing.
They are attached in the starting post.

[geoand]

Can you perhaps try 2.5.0.Final as well?

Furthermore, is this regression only limited to dev-mode?

[Postremus]

@geoand

There is no difference between 2.5.0.Final (2.474s) and 2.5.0.CR1 (2.476s).
There is also no difference when running as fast jar between 2.5.0 (0.877s) and 1.13.1.Final (0.876s).

The regression therefore only affects dev mode.

[gsmet]

There is a nice documentation about how to profile dev mode here: https://github.com/quarkusio/quarkus/blob/main/TROUBLESHOOTING.md#profiling-application-dev-mode-with-async-profiler If you're interested in digging a bit more by yourself, that would be a good starting point.

…

On Mon, Nov 22, 2021 at 10:11 PM Martin Panzer ***@***.***> wrote: @geoand <https://github.com/geoand> There is no difference between 2.5.0.Final (2.474s) and 2.5.0.CR1 (2.476s). There is also no difference when running as fast jar between 2.5.0 (0.877s) and 1.13.1.Final (0.876s). The regression therefore only affects dev mode. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#21552 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAJYOBPJJ7C5LELCYW3UTBTUNKWW5ANCNFSM5IKWMYYA> . Triage notifications on the go with GitHub Mobile for iOS <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>.

[geoand]

The regression therefore only affects dev mode.

Good to know, thanks

[stuartwdouglas]

I also had a look and I see a ~100ms regression, although it is really not clear what is causing it.

What is also odd is that I see 2.5 producing a lot less bytecode in the final jar, even though the startup time is slower.

[gsmet]

I'm not sure we should close this one. For me, there's a good chance all the improvements @Postremus did are unrelated to the regression we encounter.

[Postremus]

Current measurements, as reported by the started in <some amount>s. line.

mvn clean compile quarkus:dev
2.2.3.Final: 2.355s
2.5.1.Final: 2.526s
main (4a48d78): 2.361

force restart (s)
2.2.3.Final: 0.764s
2.5.1.Final: 0.794s
main (4a48d78): 0.585s

Difference between 2.2.3.Final and 2.5.1.Final:
quarkus:dev ~ 170ms
force restart: 30ms

This shows that @gsmet is right. No buildstep or other deployment action is responsible for the regression.
Something before that is already slower.
Will continue investigating..

Still, the savings will translate to a faster hot deployment cycle, which is nice. :)

[gsmet]

@Postremus yeah I totally agree your work has been great. I just think maybe we could even further improve things by finding the source of the original regression.

[famod]

finding the source of the original regression

git bisect might help. 🤔

[gsmet]

Yeah first thing would be to find the version(s) introducing the regression and then git bisect.

…

On Mon, Dec 6, 2021 at 6:18 PM Falko Modler ***@***.***> wrote: finding the source of the original regression git bisect might help. 🤔 — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#21552 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAJYOBPR34SIC2ZB227UBQTUPTV77ANCNFSM5IKWMYYA> . Triage notifications on the go with GitHub Mobile for iOS <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>.

[maxandersen]

just a random test to make, run with "-Dquarkus.devservices.enabled=false" and/or "-Dquarkus.console.basic=true" and see if makes difference.

There been some changes in these areas that I could suspect adding at least some unwarranted pauses.

[geoand]

-Dquarkus.console.basic=true I had also seen when looking at something else...

[Postremus]

just a random test to make, run with "-Dquarkus.devservices.enabled=false" and/or "-Dquarkus.console.basic=true" and see if makes difference.

There been some changes in these areas that I could suspect adding at least some unwarranted pauses.

Makes no real difference on 2.5.1.Final.
With these parameters: 2.569s
without: 2.575s

For a future bisect:
2.2.3.Final: 2.390s
2.3.1.Final: 2.521s
2.4.2.Final: 2.680s
2.5.1.Final: 2.577s

[famod]

Btw, I suggest to use -Dno-test-modules -pl '!docs' for the bisect runs to save a little time.
You could also try to to list all your extensions via -pl and use -am but the list of istalled extensions becomes long very quickly.

PS: I'd also recommend to try -XX:TieredStopAtLevel=1 -Xverify:none -Djansi.passthrough=true in MAVEN_OPTS.

[Postremus]

fyi, Current measurements, as reported by the started in s. line.

mvn clean compile quarkus:dev
2.5.1.Final: 2.546s
2.6.0.CR1: 2.383s
main (8344034): 2.087s

force restart (s)
2.5.1.Final: 0.795s
2.6.0.CR1: 0.591s
main (8344034): 0.346s

[famod]

Great numbers @Postremus, nice job!
Do you see potential for even more improvements?

[geoand]

Wonderful!

[Postremus]

Great numbers @Postremus, nice job! Do you see potential for even more improvements?

yes. At least about another 100ms.

[aloubyansky]

We could get more if we had better integration with ClassPathElement in the BuildSteps/BuildItems. I am touching that too in my branch.

[Postremus]

I did a few fresh measurements, since 2.7.0.CR1 is out.
Numbers are the average of 3 runs.

mvn clean compile quarkus:dev
2.5.2.Final: 2442ms
2.6.2.Final: 2212ms
2.7.0.CR1: 1970ms

force restart (s)
2.5.2.Final: 693ms
2.6.2.Final: 500ms
2.7.0.CR1: 247ms

[gsmet]

Thanks for all this work, Martin! It's this sort of thing that makes Quarkus more pleasant when used daily.

…

On Wed, Jan 19, 2022 at 6:58 PM Martin Panzer ***@***.***> wrote: I did a few fresh measurements, since 2.7.0.CR1 is out. Numbers are the average of 3 runs. mvn clean compile quarkus:dev 2.5.2.Final: 2442ms 2.6.2.Final: 2212ms 2.7.0.CR1: 1970ms force restart (s) 2.5.2.Final: 693ms 2.6.2.Final: 500ms 2.7.0.CR1: 247ms — Reply to this email directly, view it on GitHub <#21552 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAJYOBI42KL2CG3JPSVU22DUW33S7ANCNFSM5IKWMYYA> . Triage notifications on the go with GitHub Mobile for iOS <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>. You are receiving this because you were mentioned.Message ID: ***@***.***>

[geoand]

Awesome improvement!

[maxandersen]

Excellent. I really felt this in my testing today of main branch. Thank you.

[famod]

@Postremus you should make This saves about x ms of dev mode startup time. your permanent signature. 😉

Thanks, also to @aloubyansky!

[geoand]

Perhaps we could also have a blog post documenting what happened and it was addressed?

[gsmet]

I think we can close this one now.

Thanks for all your work on this @Postremus .