Faster startup of @QuarkusTest (disable web-server?)

[AntonFagerberg]

This is a feature request to speed up tests using the @QuarkusTest notation. In our applications we do not use "HTTP based testing" but do "normal" unit testing. It is however nice to use the @QuarkusTest annotation since we can then access to the @Inject, @InjectMock, etc functionality. Essentially, we do what's described here https://quarkus.io/guides/getting-started-testing#injection-into-tests & here https://quarkus.io/guides/getting-started-testing#quarkus_mock, which I think is quite common.

The problem is that even though we do not use HTTP based testing a web server will be started before every run which adds several seconds of delay. Starting a Unit test with @QuarkusTest takes ~7 seconds on my machine whereas a similar test without it takes less than a second. This adds quite a bit of friction to the developer experience.

I'm guessing this is caused by the startup of the web server (but I don't know for sure). If the web server startup could be disabled but still give access to the annotations that are helpful for testing, I think that would be of great value and offer a nicer testing experience.

[stuartwdouglas]

It would not be the web server, on most machines that is low hundreds of ms. Can you create a flame graph using https://github.com/jvm-profiling-tools/async-profiler and we can have a look at what is taking up the startup time.

[AntonFagerberg]

I'm not familiar with how profiling works but I have tried to generate the three different profiles I could. Hope they are helpful. profiles.zip

[geoand]

Let's say Quarkus had this functionality, what would your test look like?

[famod]

FWIW, we have just split up our single module Maven project into a 5 modules project. There is a core module without any REST resources/controller but still we had to add some http config due to project sepcific needs (e.g. insecure-requests are ok for tests, but it is switched off in the main application.yaml). @QuarkusTests in that core module simply @Inject services or other beans and test those "directly". We mostly use Spring repos but we do also have tests that inject EntityManager and that are testing coarse-grained entity methods.

[geoand]

So in this case, all you are doing is interacting with the database taking advantage of the fact that Quarkus has wired up all the necessary beans for you?

[famod]

Yes, and that the same db config is used as for rest assured tests etc.

[geoand]

And is there any indication that the web layer is slowing down the tests significantly?

[famod]

@geoand I don't think web layer is the main problem for me. I was referring to http mostly because of the surprising need to configure something you don't actually use.

What I can give you right away is this:

$ mvn -Dquarkus.debug.print-startup-times=true -Dtest=FooTest -f core
[INFO] Error stacktraces are turned on.
[INFO] Scanning for projects...
[INFO] gitflow-incremental-builder is disabled.
[INFO]
[INFO] ---------------< de.somecompany.someproject:register-core >----------------
[INFO] Building register-core 1.0.0-dev1-SNAPSHOT
[INFO] --------------------------------[ jar ]---------------------------------
[INFO]
[INFO] --- maven-enforcer-plugin:3.0.0-M3:enforce (enforce-tool-versions) @ register-core ---
[INFO]
[INFO] --- jacoco-maven-plugin:0.8.7:prepare-agent (default-prepare-agent) @ register-core ---
[INFO] argLine set to -javaagent:/home/fmo/.m2/repository/org/jacoco/org.jacoco.agent/0.8.7/org.jacoco.agent-0.8.7-runtime.jar=destfile=/home/fmo/proj/someproject/register/dev1/core/target/jacoco.exec,includes=**/somecompany/someproject/**,excludes=**/generated/**,**/test/**,**/*MapperImpl.class,**/*_.class,exclclassloader=*QuarkusClassLoader
[INFO]
[INFO] --- flatten-maven-plugin:1.2.7:flatten (flatten) @ register-core ---
[INFO] Generating flattened POM of project de.somecompany.someproject:register-core:jar:1.0.0-dev1-SNAPSHOT...
[INFO]
[INFO] --- maven-resources-plugin:3.2.0:resources (default-resources) @ register-core ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] Using 'UTF-8' encoding to copy filtered properties files.
[INFO] Copying 24 resources
[INFO]
[INFO] --- maven-compiler-plugin:3.8.1:compile (default-compile) @ register-core ---
[INFO] Nothing to compile - all classes are up to date
[INFO]
[INFO] --- jandex-maven-plugin:1.1.0:jandex (make-index) @ register-core ---
[INFO] Saving Jandex index: /home/fmo/proj/someproject/register/dev1/core/target/classes/META-INF/jandex.idx
[INFO]
[INFO] --- maven-resources-plugin:3.2.0:testResources (default-testResources) @ register-core ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] Using 'UTF-8' encoding to copy filtered properties files.
[INFO] Copying 4 resources
[INFO]
[INFO] --- maven-compiler-plugin:3.8.1:testCompile (default-testCompile) @ register-core ---
[INFO] Changes detected - recompiling the module!
[INFO] Compiling 81 source files to /home/fmo/proj/someproject/register/dev1/core/target/test-classes
[WARNING] Implicitly compiled files were not subject to annotation processing.
[INFO]
[INFO] --- maven-surefire-plugin:3.0.0-M5:test (default-test) @ register-core ---
[INFO] Surefire report directory: /home/fmo/proj/someproject/register/dev1/core/target/surefire-reports
[INFO]
[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[INFO] Running de.somecompany.someproject.register.FooTest
Build step BlockingOperationControlBuildStep.blockingOP completed in: 1ms
Build step LoggingResourceProcessor.setupLoggingStaticInit completed in: 1ms
Build step MutinyProcessor.buildTimeInit completed in: 26ms
Build step RestClientProcessor.setup completed in: 4ms
Build step AgroalProcessor.generateDataSourceSupportBean completed in: 1ms
Build step SmallRyeContextPropagationProcessor.buildStatic completed in: 0ms
Build step NativeImageConfigBuildStep.build completed in: 1ms
Build step JacksonProcessor.pushConfigurationBean completed in: 1ms
Build step PanacheJpaCommonResourceProcessor.buildNamedQueryMap completed in: 1ms
Build step HibernateOrmProcessor.build completed in: 0ms
Build step HibernateOrmCdiProcessor.generateDataSourceBeans completed in: 2ms
Build step HibernateValidatorProcessor.build completed in: 24ms
Build step SyntheticBeansProcessor.initStatic completed in: 1ms
Build step PanacheHibernateResourceProcessor.build completed in: 1ms
Build step HibernateOrmProcessor.build completed in: 17ms
Build step ArcProcessor.generateResources completed in: 1140ms
Build step ArcProcessor.initTestApplicationClassPredicateBean completed in: 1ms
Build step ResteasyCommonProcessor.setupResteasyInjection completed in: 1ms
Build step RestClientProcessor.registerProviders completed in: 50ms
Build step BootstrapConfigSetupBuildStep.setupBootstrapConfig completed in: 0ms
Build step NettyProcessor.eagerlyInitClass completed in: 1ms
Build step RuntimeConfigSetupBuildStep.setupRuntimeConfig completed in: 83ms
Build step ShutdownListenerBuildStep.setupShutdown completed in: 0ms
Build step AgroalProcessor.generateDataSourceBeans completed in: 22ms
Build step ThreadPoolSetup.createExecutor completed in: 13ms
Build step MutinyProcessor.runtimeInit completed in: 1ms
Build step HibernateOrmProcessor.setupPersistenceProvider completed in: 2ms
Build step NettyProcessor.registerEventLoopBeans completed in: 0ms
Build step ArcProcessor.setupExecutor completed in: 0ms
Build step SmallRyeContextPropagationProcessor.build completed in: 2ms
Build step LiquibaseProcessor.createBeans completed in: 2ms
2021-07-27 13:36:47,463 WARN  [io.qua.config] (main) 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-07-27 13:36:48,660 WARN  [io.qua.hib.orm.run.pro.ProxyDefinitions] (main) Unable to find a build time generated proxy for entity com.blazebit.persistence.impl.function.entity.ValuesEntity
Build step LoggingResourceProcessor.setupLoggingRuntimeInit completed in: 8ms
Build step ConfigGenerationBuildStep.checkForBuildTimeConfigChange completed in: 10ms
Build step NarayanaJtaProcessor.build completed in: 11ms
Build step ConfigBuildStep.registerConfigClasses completed in: 10ms
Build step BlazePersistenceCdiProcessor.generateBeans completed in: 1ms
Build step SchedulerProcessor.build completed in: 0ms
Build step SyntheticBeansProcessor.initRuntime completed in: 1ms
Build step LiquibaseProcessor.startLiquibase completed in: 1ms
Build step ConfigBuildStep.validateConfigProperties completed in: 0ms
Build step HibernateOrmProcessor.startPersistenceUnits completed in: 1119ms
2021-07-27 13:36:50,029 INFO  [io.qua.sch.run.SimpleScheduler] (main) Simple scheduler is disabled by config property and will not be started
2021-07-27 13:36:50,157 INFO  [de.som.som.reg.per.liq.LiquibaseMigrator] (main) migrating with labels: test, db url is: jdbc:h2:mem:testdb
2021-07-27 13:36:51,450 INFO  [liq.lockservice] (main) Successfully acquired change log lock
2021-07-27 13:36:51,947 INFO  [liq.changelog] (main) Creating database history table with name: public.DATABASECHANGELOG
2021-07-27 13:36:51,950 INFO  [liq.changelog] (main) Reading from public.DATABASECHANGELOG
2021-07-27 13:36:52,077 INFO  [liq.changelog] (main) Data loaded from /db/initdata/catalog_values.csv into catalog_value
2021-07-27 13:36:52,077 INFO  [liq.changelog] (main) Data deleted from catalog_value
2021-07-27 13:36:52,122 INFO  [liq.changelog] (main) Data loaded from /db/initdata/catalog_value_metadata.csv into catalog_value_metadata
2021-07-27 13:36:52,124 INFO  [liq.changelog] (main) ChangeSet catalog_values.xml::someproject-320-add-catalog-values::mrlw ran successfully in 128ms
2021-07-27 13:36:52,140 INFO  [liq.changelog] (main) Custom SQL executed
2021-07-27 13:36:52,164 INFO  [liq.changelog] (main) Data loaded from /db/testdata/accounts.csv into account
2021-07-27 13:36:52,177 INFO  [liq.changelog] (main) Data loaded from /db/testdata/account_roles.csv into account_roles
2021-07-27 13:36:52,179 INFO  [liq.changelog] (main) Custom SQL executed
2021-07-27 13:36:52,180 INFO  [liq.changelog] (main) ChangeSet users.xml::insert-or-update-test-accounts::fwi ran successfully in 46ms
2021-07-27 13:36:52,184 INFO  [liq.lockservice] (main) Successfully released change log lock
Build step LifecycleEventsBuildStep.startupEvent completed in: 2159ms
2021-07-27 13:36:52,186 INFO  [io.quarkus] (main) Quarkus 2.0.3.Final on JVM started in 8.492s.
2021-07-27 13:36:52,186 INFO  [io.quarkus] (main) Profile test activated.
2021-07-27 13:36:52,187 INFO  [io.quarkus] (main) Installed features: [agroal, blaze-persistence, cdi, config-yaml, hibernate-orm, hibernate-orm-panache, hibernate-validator, jacoco, jdbc-h2, jdbc-mariadb, liquibase, narayana-jta, rest-client, scheduler, smallrye-context-propagation, spring-data-jpa, spring-di]
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 9.157 s - in de.somecompany.someproject.register.FooTest
2021-07-27 13:36:52,273 INFO  [io.quarkus] (main) Quarkus stopped in 0.008s
[INFO]
[INFO] Results:
[INFO]
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0
[INFO]
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  27.530 s
[INFO] Finished at: 2021-07-27T13:37:02+02:00
[INFO] ------------------------------------------------------------------------

Notes:

• FooTest is totally empty, just a @QuarkusTest with an empty @Test method
• compilation etc. takes around 5 secs
• there is a noticable "lag" of a few seconds between Running de.somecompany.someproject.register.FooTest and the first build step printout
• Liquibase takes its toll, but nothing too excessive (~2s)
• there is a noticable "lag" of a few seconds after Quarkus stopped

[geoand]

Thanks for the information

[stuartwdouglas]

The 'Quarkus Stopped' lag should be fixed upstream.

So out of the 8s we have: 1 for arc generating resources 1 for hibernate 2 for liquibase

Which leaves 4s. My guess would be this is actually starting hibernate/arc, but without a profile its hard to say.

[famod]

The 'Quarkus Stopped' lag should be fixed upstream.

I see it's gone already in 2.1.0. 👍

My guess would be this is actually starting hibernate/arc

h2 will take its toll as well.

With 2.1.0 and some Maven tweaking (surefire:test@default-test instead of test), I'm down to ~12s for the whole call.

Quarkus 2.1.0.Final on JVM started in 8.716s.

So that is more or less the same.

But this is suprising (wasn't there with 2.0.3):

WARN  [io.qua.config] (main) Unrecognized configuration key "quarkus.http.test-port" was provided; it will be ignored; verify that the dependency extension for this configuration is set or that you did not make a typo

Has something changed wrt web layer in tests that don't actually use it?

[geoand]

WARN [io.qua.config] (main) Unrecognized configuration key "quarkus.http.test-port" was provided; it will be ignored; verify that the dependency extension for this configuration is set or that you did not make a typo

Has something changed wrt web layer in tests that don't actually use it?

Not that I know of. If you have a sample that shows this problem, I'll take a look

[famod]

WDYT about exposing startSocket as a config property? https://github.com/quarkusio/quarkus/blob/2.1.2.Final/extensions/vertx-http/deployment/src/main/java/io/quarkus/vertx/http/deployment/VertxHttpProcessor.java#L292

It's not so much because of performance concerns but DRY config instead: With Quarkus 2.1 I get that warning I posted previously in my core module which is providing some common (http) test config for all other modules that depend on core. If startSocket was exposed, I could switch http off in modules that just happen to depend on quarkus-vertx-http like quarkus-cxf (client only) or quarkus-oidc-client, but don't actually need a http server. Then I could move the http config to the one module that actually needs it for testing (api module for our UI).

What would be even better is that extension could tell quarkus-vertx-http: Ok I need you, but not your server part!

PS: I haven't made any progress on profiling, sorry.

[geoand]

What would be even better is that extension could tell quarkus-vertx-http: Ok I need you, but not your server part!

Well, we can likely have a configuration property for that. I don't think it's high on anyone's agenda, but perhaps someone creating a draft PR and then starting a thread on quarkus-dev mailing list will get things going

[famod]

I finally managed to produce a flamegraph, captured from a surefire run of an empty QuarkusTest via:

-DargLine='-agentpath:/home/famod/proj/async-profiler-1.8.6-linux-x64/build/libasyncProfiler.so=start,event=cpu,file=profile.html,flamegraph'

Is that of any help?

[stuartwdouglas]

Unfortunately nothing really stands out as being an easy target. Liqibase is taking up a fair bit of time, as is the hibernate entity enhancer and Jacoco transformation, but I don't know if there is much we can do about it.

[stuartwdouglas]

BTW how long did startup take in this case?

[famod]

I took Liquibase out of the equation and added -Dquarkus.debug.print-startup-times=true:

2021-08-30 18:19:32,178 [INFO] -------------------------------------------------------
2021-08-30 18:19:32,178 [INFO]  T E S T S
2021-08-30 18:19:32,179 [INFO] -------------------------------------------------------
2021-08-30 18:19:33,278 [INFO] Running de.somecompany.FooQuarkusTest
Build step LoggingResourceProcessor.setupLoggingStaticInit completed in: 1ms
Build step MutinyProcessor.buildTimeInit completed in: 24ms
Build step BlockingOperationControlBuildStep.blockingOP completed in: 0ms
Build step RestClientProcessor.setup completed in: 3ms
Build step AgroalProcessor.generateDataSourceSupportBean completed in: 1ms
Build step SmallRyeContextPropagationProcessor.buildStatic completed in: 0ms
Build step NativeImageConfigBuildStep.build completed in: 0ms
Build step JacksonProcessor.pushConfigurationBean completed in: 1ms
Build step PanacheJpaCommonResourceProcessor.buildNamedQueryMap completed in: 1ms
Build step HibernateOrmProcessor.build completed in: 0ms
Build step HibernateOrmCdiProcessor.generateDataSourceBeans completed in: 2ms
Build step HibernateValidatorProcessor.build completed in: 17ms
Build step SyntheticBeansProcessor.initStatic completed in: 1ms
Build step PanacheHibernateResourceProcessor.build completed in: 1ms
Build step HibernateOrmProcessor.build completed in: 12ms
Build step ArcProcessor.generateResources completed in: 966ms
Build step ArcProcessor.initTestApplicationClassPredicateBean completed in: 1ms
Build step ResteasyCommonProcessor.setupResteasyInjection completed in: 2ms
Build step RestClientProcessor.registerProviders completed in: 46ms
Build step BootstrapConfigSetupBuildStep.setupBootstrapConfig completed in: 0ms
Build step RuntimeConfigSetupBuildStep.setupRuntimeConfig completed in: 35ms
Build step NettyProcessor.eagerlyInitClass completed in: 1ms
Build step ShutdownListenerBuildStep.setupShutdown completed in: 1ms
Build step NettyProcessor.registerEventLoopBeans completed in: 0ms
Build step AgroalProcessor.generateDataSourceBeans completed in: 45ms
Build step ThreadPoolSetup.createExecutor completed in: 10ms
Build step MutinyProcessor.runtimeInit completed in: 1ms
Build step LiquibaseProcessor.createBeans completed in: 3ms
Build step ArcProcessor.setupExecutor completed in: 0ms
Build step SmallRyeContextPropagationProcessor.build completed in: 2ms
Build step HibernateOrmProcessor.setupPersistenceProvider completed in: 2ms
2021-08-30 18:19:37,313 WARN  [io.qua.config] (main) Unrecognized configuration key "quarkus.http.test-port" 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-08-30 18:19:37,313 WARN  [io.qua.config] (main) 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-08-30 18:19:37,313 WARN  [io.qua.config] (main) Unrecognized configuration key "quarkus.http.insecure-requests" 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-08-30 18:19:38,324 WARN  [io.qua.hib.orm.run.pro.ProxyDefinitions] (main) Unable to find a build time generated proxy for entity com.blazebit.persistence.impl.function.entity.ValuesEntity
Build step LoggingResourceProcessor.setupLoggingRuntimeInit completed in: 7ms
Build step NarayanaJtaProcessor.build completed in: 13ms
Build step ConfigGenerationBuildStep.checkForBuildTimeConfigChange completed in: 9ms
Build step ConfigBuildStep.registerConfigClasses completed in: 8ms
Build step BlazePersistenceCdiProcessor.generateBeans completed in: 2ms
Build step SchedulerProcessor.build completed in: 0ms
Build step SyntheticBeansProcessor.initRuntime completed in: 0ms
Build step LiquibaseProcessor.startLiquibase completed in: 1ms
Build step HibernateOrmProcessor.startPersistenceUnits completed in: 1059ms
Build step ConfigBuildStep.validateConfigProperties completed in: 1ms
2021-08-30 18:19:39,597 INFO  [io.qua.sch.run.SimpleScheduler] (main) Simple scheduler is disabled by config property and will not be started
Build step LifecycleEventsBuildStep.startupEvent completed in: 6ms
2021-08-30 18:19:39,601 INFO  [io.quarkus] (main) Quarkus 2.1.2.Final on JVM started in 5.762s.
2021-08-30 18:19:39,601 INFO  [io.quarkus] (main) Profile test activated.
2021-08-30 18:19:39,602 INFO  [io.quarkus] (main) Installed features: [agroal, blaze-persistence, cdi, config-yaml, hibernate-orm, hibernate-orm-panache, hibernate-validator, jacoco, jdbc-h2, jdbc-mariadb, liquibase, narayana-jta, rest-client, scheduler, smallrye-context-propagation, spring-data-jpa, spring-di]
2021-08-30 18:19:39,710 [INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 6.411 s - in de.somecompany.FooQuarkusTest
2021-08-30 18:19:39,686 INFO  [io.quarkus] (main) Quarkus stopped in 0.009s

So, until the first "real" log messages from Quarkus (those config warnings), ~4s are spent. ArcProcessor.generateResources takes ~25% of this, but the rest is not really spent in build steps as it seems.

The flamegraph for that is here.

Btw, what's that CompilerBroker stuff about? JIT compilation?

PS: It would be nice if quarkus.debug.print-startup-times would also log a timestamp.

PPS: Surefire also takes one second before actually running that specific test, JVM forking overhead I suppose.

[famod]

-XX:TieredStopAtLevel=1 -Xverify:none helps quite a bit for that CompilerBroker overhead, bringing Quarkus 2.1.2.Final on JVM started in x down by 2 seconds (~3.6 instead of ~5.7)!

[geoand]

PS: It would be nice if quarkus.debug.print-startup-times would also log a timestamp.

Open an issue please - this is an easy ask to fulfill :)

[geoand]

966ms for generating Arc sources seems pretty terrible...

[famod]

966ms for generating Arc sources seems pretty terrible...

@mkouba do you have some hints where to look in ArC? Might be the number of dependencies? We have 276 according to mvn dependency:tree.

[mkouba]

@famod @geoand @stuartwdouglas Well, the output of quarkus.debug.print-startup-times is actually quite misleading because ArcProcessor.generateResources completed in: 966ms has nothing to do with generating resources. It includes ArcRecorder.getContainer() and ArcRecorder.initBeanContainer() recorder invocations where the CDI container is started, @Initialized(ApplicationScoped.class) observers are notified, and all BeanContainerListeners are called. If possible try to enable the DEBUG level for the io.quarkus.arc category. You should see some Bean container listener X finished N ms messages and also the number of registered beans.

[famod]

For some super weird reason, I don't see that debug message, even with the proper config. But I do see DEBUG [io.qua.arc.impl] (main) ArC DI container shut down at the end of the test. I had to switch the code to infof() (instead of debugf()). 😕

With the above:

INFO  [io.qua.arc.run.ArcRecorder] (main) Bean container listener io.quarkus.hibernate.validator.runtime.HibernateValidatorRecorder$1 finished in 273 ms
INFO  [io.qua.arc.run.ArcRecorder] (main) Bean container listener io.quarkus.hibernate.orm.runtime.HibernateOrmRecorder$1 finished in 237 ms

PS: With the JVM flags that build step is now down to ~ 600ms (from almost ~1000ms) and so both hibernate listeners make up almost all of the ArcProcessor.generateResources runtime.

[stuartwdouglas]

Can you generate a new profile with these updates?

[mkouba]

When you look at the flamegraph from https://github.com/quarkusio/quarkus/issues/14927#issuecomment-908493292 a great deal of the time is taken by ArcRecorder.initBeanContainer() where half is the io/quarkus/hibernate/orm/runtime/HibernateOrmRecorder$1.created and the other half is io/quarkus/hibernate/validator/runtime/HibernateValidatorRecorder$1.created.

[famod]

@mkouba yeah, that's what the log output is saying as well.

@Sanne is this to be expected or is this out of the ordinary?

Bean container listener io.quarkus.hibernate.validator.runtime.HibernateValidatorRecorder$1 finished in 273 ms
Bean container listener io.quarkus.hibernate.orm.runtime.HibernateOrmRecorder$1 finished in 237 ms

@stuartwdouglas

Can you generate a new profile with these updates?

It's already linked, but I'll link it again: profile.

[famod]

@stuartwdouglas

Can you generate a new profile with these updates?

It's already linked, but I'll link it again: profile.

Ah, sorry, that wasn't the right one. Here is a brand new one: profile.zip

[Sanne]

Well yes both of ORM and Validator are known to be quite expensive to boot, but I'll need to have a look to see if the specific costs here are expected.

[Sanne]

So among costs there is Hibernate ORM's enhancement of entities via ByteBuddy, combined with Jacoco based enhancement? I don't know much about this last one but considering the ORM one is expensive, I'd not be surprised if the other one is as well.

It seems the Jacoco enhancer has the same problem as the ORM one: it's bypassing the visitor API to work on the byte array instead; this is not optimal and a known limitation of the Hibernate one as well; perhaps it's time to look at alternative options to optimise both of these.

However, both transformations are supposedly using a Quarkus cache that Stuart designed to minimize cost from enhancement, and even if we could improve this by say doubling enhancmenet speed, from the samples it seem they are responsible for less than 20% of total time anyway for enhancement (counting ORM+Jacoco), plu some ~3.5% for ORM's enhanced proxies (in a different section of the flamegraph).

If this is taking >7 seconds there is something else at play for sure as well. Perhaps not much memory?

Also I don't actually see Hibernate Validator in the graph, besides the ~2,3% cost in the main pillar.

It strikes me t hat there is an extremely high and thing flame triggered from QuarkusAugmentor - someone should probably look at making that non-recursive, but since it's a very narrow flame it's probably unrelated.

[famod]

Thanks @Sanne for the detailed answer!

combined with Jacoco based enhancement

Yeah, I too noticed jacoco. And I've just realized that we are not setting any exclusions like we do for the jacoco-maven-plugin. We have many generated classes, so setting exclusions might help a bit!

Perhaps not much memory?

I'll check.

[stuartwdouglas]

Something to bear in mind with the transformation stuff is that even though it is expensive it should be done in a thread pool, so even if it is taking up N ms on the graph, in real time it should only be N/cores. The cache that Sanne mentions is more for dev mode restarts, and won't really help with testing startup time.

[famod]

Interesting, mvn clean ... triggers Maven Bootstrapping big time, from under 10s to over 14s (resolveAppModel() with > 20%).

[famod]

Thanks @Sanne for the detailed answer!

combined with Jacoco based enhancement

Yeah, I too noticed jacoco. And I've just realized that we are not setting any exclusions like we do for the jacoco-maven-plugin. We have many generated classes, so setting exclusions might help a bit!

Hm, getting very mixed results with includes/excludes. Maybe I'm using the wrong format. Will have to take a closer look.

Perhaps not much memory?

I'll check.

Nope, doesn't help.

[geoand]

I am wondering if it makes sense to have something like the following:

@QuarkusTest
@ExcludeExtension(groupId="io.quarkus", artifactId="quarkus-flyway")
public class MyCustomTest {

}

The result would be that the test would setup Quarkus bootstrap in a way that completely excludes io.quarkus:quarkus-flyway from the build classpath, therefore the resulting application would behave as though that extension never existed.

This could obviously lead to problems depending on what extension was excluded, so it would be up to the user the exclude only things that would not be break the application (although we could perhaps also introduce some kind of annotation for excluding classes and/or packages).

WDYT?

[mkouba]

This could obviously lead to problems depending on what extension was excluded, so it would be up to the user the exclude only things that would not be break the application (although we could perhaps also introduce some kind of annotation for excluding classes and/or packages).

Hm, so any exclusion like this would have to result in an app restart, or? Would it make sense to extend the QuarkusTestProfile instead?

[geoand]

Hm, so any exclusion like this would have to result in an app restart, or?

Yes, if different exclusions are needed, a restart will be necessary

Would it make sense to extend the QuarkusTestProfile instead?

That's also an option.

[famod]

A QuarkusTestProfile would also automatically be covered by our TestClassOrderer. Downside: You need to write more code.

I don't want to overcomplicate this, but a restart is a big price to pay. So I was wondering how "binding" that exclusion should be. Imagine a larger set of tests, some need more extensions than others, but if you run them all it's better (from the runtime perspective) to only boot up everything once. Then those tests that don't need e.g. flyway (to stay with that example) wouldn't mind if it's around regardless.

[stuartwdouglas]

A big problem with this is how you exclude transient dependencies. e.g. if your application depends on quarkus-resteasy, and you exclude it, do you still get the HTTP server brought in by vertx-http. If you exclude vertx-http then any of its deps should also be excluded.

I like the idea in theory, but we need to give some thought to how to handle these cases.

[geoand]

Yeah, my thought was that bootstrap would exclude all the Quarkus dependencies that depended on whatever was excluded. That could still get us into trouble, but I think it's the most logical way to do it.

@aloubyansky I assume this is something that could be done relatively easily, correct?

[geoand]

@famod I think that would actually be pretty dangerous behavior. My preference would be that exclusions are taken at face value.

But good point about ordering tests, so QuarkusTestProfile is likely the way to go.

[geoand]

I think having something (experimental) as described above would be a nice addition for 2.8 or 2.9. If we agree on the basic idea, I can move ahead with an implementation and then we can discuss more when I have something to show.

[famod]

@famod I think that would actually be pretty dangerous behavior. My preference would be that exclusions are taken at face value.

Well, it shouldn't be the default because some tests might actually fail if an extension is still around. So what I'm thinking about is a flag parameter of that new annotation, to opt in into that "lenient" behavior.

Without such a mode, I really see the risk that this whole @ExcludeExtension feature will actually slow down overall runtime instead of speeding things up. This is my POV from looking at the tests my Quarkus projects had/have so far and it's always a mix. You hardly ever have just one "category" of tests per module.

But sure, it's important to get starting somewhere and improve gradually. 👍

[geoand]

Without such a mode, I really see the risk that this whole @ExcludeExtension feature will actually slow down overall runtime instead of speeding things up.

Yup, that could certainly happen, depending on the use case.

[aloubyansky]

Yeah, my thought was that bootstrap would exclude all the Quarkus dependencies that depended on whatever was excluded. That could still get us into trouble, but I think it's the most logical way to do it.

@aloubyansky I assume this is something that could be done relatively easily, correct?

Not exactly easy but could be done. It's just it would have to be implemented differently for Maven and Gradle, where it will be more tricky. We actually still don't support even forced dependencies in Gradle, although getting closer to that. So, QuarkusProdModeTest.setForcedDependencies(forcedDeps) are currently ignored, fyi @glefloch

[geoand]

Ah, I wasn't aware of that. Thanks for the information

[glefloch]

@aloubyansky, forcedDependencies needs resolution and proper support in both gradle and maven, but for resource exclusion, it can directly be handled in the after the resolution when building the quarkus classloader right ?

[Sanne]

hey all - I'm a little confused by the direction of the conversation.

This discussion seemed it had stalled ~6 months ago with https://github.com/quarkusio/quarkus/issues/14927#issuecomment-913849578 - which concluded that @famod was going to have a closer look into jacoco.

Then 2 days ago the topic is resurrected but going in a different direction; I really don't mind if you all find a nice solution to not need starting the webserver :)

But let's please first make sure this is actually useful? There seems to be no meaningful data supporting this direction.

[aloubyansky]

@aloubyansky, forcedDependencies needs resolution and proper support in both gradle and maven,

forcedDependencies are properly supported in Maven (except what Ioannis has been working on).

but for resource exclusion, it can directly be handled in the after the resolution when building the quarkus classloader right ?

No, exclusions are filters that have to be applied by the resolver itself. We can't compensate for it properly after a configuration has been resolved. In Gradle, I suppose it could be done using https://docs.gradle.org/current/javadoc/org/gradle/api/artifacts/Configuration.html#exclude-java.util.Map-

[geoand]

@Sanne what I am proposing is not for the web server per-se, it's a general solution.

Not sure what data you would like to see to support the usefulness of the proposal