Quarkus: Flyway Startup Highly Impacts Quarkus Start-up Times

[sirAlexanderT]

Describe the bug
I had an app that started in approx. 0.5sec - 1 sec .. I then included flyway and the startup time went up to 2.9 secs "Even when No migration is necessary".. this is in .jvm mode. Is there a way of bringing this time down? shame as this edges closer to other frameworks start up times.

Compromises on the Quarkus speed promise and prevents adoption.

Similar to the liquibase issue raise here I guess
https://github.com/quarkusio/quarkus/issues/8942

Expected behavior
startup times between 0.5 - 1 sec

Actual behavior
startup times of a "whooping" 2.9 secs
(powered by Quarkus 1.3.2.Final) started in 2.978s.

To Reproduce
Steps to reproduce the behavior:

1. Quarkus version 1.3.2
2. JDK 11
3. Project has the following installed features

Installed features: [agroal, cdi, flyway, hibernate-orm, hibernate-orm-panache, jdbc-mysql, mutiny, narayana-jta, resteasy, resteasy-jackson, resteasy-mutiny, smallrye-health, smallrye-metrics, smallrye-openapi, spring-data-jpa, spring-di, swagger-ui]

Configuration

# Add your application.properties here, if applicable.

Screenshots
(If applicable, add screenshots to help explain your problem.)

Environment (please complete the following information):

• Output of uname -a or ver:

Darwin XXXX-MacBook-Pro.local 19.4.0 Darwin Kernel Version 19.4.0: Wed Mar 4 22:28:40 PST 2020; root:xnu-6153.101.6~15/RELEASE_X86_64 x86_64

• Output of java -version:

openjdk version "11.0.6" 2020-01-14 OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.6+10) Eclipse OpenJ9 VM AdoptOpenJDK (build openj9-0.18.0, JRE 11 Mac OS X amd64-64-Bit Compressed References 20200116_443 (JIT enabled, AOT enabled) OpenJ9 - 6968c18d7 OMR - 7a1b0239a JCL - 104cab2452 based on jdk-11.0.6+10)

• GraalVM version (if different from Java):

• Quarkus version or git rev:
  Quarkus 1.3.2.Final

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

Apache Maven 3.6.3 (cecedd343002696d0abb50b32b541b8a6ba2883f) Maven home: /usr/local/Cellar/maven/3.6.3_1/libexec Java version: 11.0.6, vendor: Eclipse OpenJ9, runtime: /Users/xxxx/.sdkman/candidates/java/11.0.6.j9-adpt Default locale: en_GB, platform encoding: UTF-8 OS name: "mac os x", version: "10.15.4", arch: "x86_64", family: "mac"

Additional context
(Add any other context about the problem here.)

[jaikiran]

Quarkus version 1.3.2

Hello @sirAlexanderT, can you try this same against 1.4.2 of Quarkus please and see if that shows any improvements?

[geoand]

If you could also try Quarkus from master (https://github.com/quarkusio/quarkus/blob/master/CONTRIBUTING.md#checking-an-issue-is-fixed-in-master), that would be great

[sirAlexanderT]

cheers @jaikiran and @geoand will do and report back

[sirAlexanderT]

@jaikiran Quarkus version 1.4.2 is pretty much the same approx. 2.9 - 3.1 secs

[sirAlexanderT]

#

[sirAlexanderT]

oops accidentally clicked on close!

[sirAlexanderT]

@geoand master still has the slow flyway issue as well

[geoand]

@sirAlexanderT thanks for checking.

Do you have a reproducer project we can use to check this?

[geoand]

One thing I see that needs to be improved, is that we always need to use the build time locations instead of the letting Flyway re-discover them at runtime.

[geoand]

I opened https://github.com/flyway/flyway/issues/2822, let's see

[machi1990]

One thing I see that needs to be improved, is that we always need to use the build time locations instead of the letting Flyway re-discover them at runtime.

+1 on this.

I opened flyway/flyway#2822, let's see

Good idea.

[sirAlexanderT]

Any update on this, my team are reluctant to go all in with Quarkus.

[geoand]

This would be easy for us to take care of once the issue I opened in Flyway is addressed.
I would suggest that you also comment on that issue in order to help the Flyway folks see its importance 😉.

On the other hand, you can always have Flyway conditionally executed depending on a Quarkus profile

[jaikiran]

Hello @sirAlexanderT, is this increase in time noticed every single time you boot up the application or is it noticed the first time you boot it up with Flyway? The reason I ask is, Flyway (as far as I know) creates certain schema specific tables for its versioning use the first time, even if there are no migrations in the application. Maybe that is impacting the timings?

[sirAlexanderT]

Hi @jaikiran startup is slow regardless. So even after flyway has created all its tables and run all migration scripts. So you can imagine how much slower it is when it needs to actually run scripts.

[gsmet]

Any update on this, my team are reluctant to go all in with Quarkus.

Not saying it's not an issue but how is it specific to Quarkus? I suppose you would have the same issue for anything using Flyway? If not, then we are missing something.

[sirAlexanderT]

Any update on this, my team are reluctant to go all in with Quarkus.

Not saying it's not an issue but how is it specific to Quarkus? I suppose you would have the same issue for anything using Flyway? If not, then we are missing something.

@gsmet My understanding is that it's a "vetted" quarkus extension. So by association, using it, you should still benefit from the whole "SUPERSONIC SUBATOMIC JAVA" promise. Well as it currently stands, using this particular extension falls short of this promise. If we want real world projects out there adopting Quarkus, then I encourage addressing issues in commonly used tools i.e. 'flyway'

[geoand]

@sirAlexanderT we try and do improve our integration with popular libraries, but there is only so much we can do on our side.
We did a similar thing with Liquibase and we are always on the look out to improve the Quarkus experience as much as possible and for as many users as possible.
Unfortunately we can't tackle every issue with every library our there as I am sure you understand :)

[gsmet]

@geoand made some improvements for 1.5.0.Final. Please try it out once it's released.

[sirAlexanderT]

@geoand made some improvements for 1.5.0.Final. Please try it out once it's released.

Will do, thanks guys much appreciated!

[geoand]

Please let us know if you still see a slow-down despite the improvement

[sirAlexanderT]

@gsmet @geoand running Quarkus 1.5.2 there is not much change I'm afraid, times seem worse by a second

on JVM (powered by Quarkus 1.5.2.Final) started in 3.377s. :(

[geoand]

If you can provide us with a sample, that would be great, because the ones we tested definetely didn't show that behavior

[sirAlexander]

@geoand as requested >> https://github.com/sirAlexander/quarkus-reproducer

[geoand]

_Copied from https://github.com/quarkusio/quarkus/issues/10215#issuecomment-648815823 (since that was the wrong issue)_

So I tried the reproducer with a MySQL database running in docker and after making sure that no migration was actually needed, I saw that a single statement in Flyway was adding around 300ms of startup time (which was almost all the time taken up by the Flyway extension). Other than that, everything appeared fine.

As for the statement in question:

Inside org.flywaydb.core.internal.jdbc.JdbcConnectionFactory there is:

JdbcUtils.openConnection(dataSource, connectRetries)

which ultimately does dataSource.getConnection() and that single call is taking ~300ms. The dataSource here is of course of type io.agroal.pool.DataSource.

@barreiro is ~300ms normal for acquiring a connection? Seem a bit long to me, but I'm no expert :)

[sirAlexander]

@geoand hmm.. thats odd, is this as jvm image on jdk 11 hs. And were you running the jar-runner? As i'm consistently getting over 3 secs. Do the machine specs affect these times?

I'm running a local MySQL instance, so not on docker. Am I running it any different?

[sirAlexander]

[geoand]

From the screenshot you show, the delay I am talking about is the one Flyway Communit... until Database ....

But yeah you are right, there is another delay (after Flyway prints its last log) that I hadn't noticed. Need to look into that, although that might be just standard Quarkus stuff that isn't printed

[geoand]

If you add debugging logging (quarkus.log.level=DEBUG) then you'll see that there is nothing weird going on - the second slowdown that is visible with INFO is explained by DEBUG logs which slow Quarkus starting Hibernate and, Netty.

So the only real slowdown I see is when Flyway obtains the initial connection

[geoand]

With Flyway enabled java -jar:

Without Flyway and again with java -jar:

[sirAlexander]

@geoand also noticed that your flyway version is different to mine? are you on a different quarkus version?

[geoand]

Quarkus build from source, but I just tried with 1.5.2.Final and the numbers are almost the same.

[sirAlexander]

@geoand my MySql version is 5.7

[geoand]

I used both MySQL 8 and MySQL 5.7, same results

[sirAlexander]

looks like it's possibly down to my dev machine then

[sirAlexander]

Thanks @geoand for taking the time to troubleshoot

[geoand]

You are welcome.

I'll go ahead and close this for now. If you find any new information of interest, feel free to post it here and we can reexamine if necessary.

[gsmet]

@sirAlexander could you give a try to https://github.com/quarkusio/quarkus/blob/master/TROUBLESHOOTING.md ?

Might help finding the root cause of the slowness.