Execution/processing time for initial databasechangelog read is excessive when switching from v3.5.3 to v4.17.2

[doakd]

Environment

Liquibase Version:
old: v3.5.3
new: v4.17.2

Liquibase Integration & Version: <Pick one: CLI, maven, gradle, spring boot, servlet, etc.>
CLI

Liquibase Extension(s) & Version:

Database Vendor & Version:
Oracle 19c

Operating System Type & Version:
Linux

Infrastructure Type/Provider: <AWC, GCS, Azure, VM, etc>
On-Prem

Description

A customer is updating from a v3.5.3 "self-supported" Liquibase solution to our v4.17.2 "officially-supported" Liquibase solution.

Using the same changelogs and database/schema:
In v3.5.3, the initial "Reading from databasechangelog" step is taking 1 second.
In v4.17.2 the initial "Reading from databasechangelog" step is taking 10 minutes, and consistently takes this long. I monitored in the database and the actual query is taking < 1 second, so I believe the additional time is spent in Liquibase code.

I also had then purge the databasechangelog table of v.3.5.3 records, and run v4.17.2 "changelog-sync" to repopulate, didn't help.

Steps To Reproduce

Actual Behavior

Expected/Desired Behavior

The "Reading from databasechangelog" should be approximately the same between v3.5.3 and v4.17.2

Screenshots (if appropriate)

v3.5.3 output:
INFO 2/9/23 10:39 AM: liquibase: Reading from TPPONPREMDEV.DATABASECHANGELOG
DEBUG 2/9/23 10:39 AM: liquibase: Executing QUERY database command: SELECT * FROM TPPONPREMDEV.DATABASECHANGELOG ORDER BY DATEEXECUTED ASC, ORDEREXECUTED ASC
DEBUG 2/9/23 10:39 AM: liquibase: master.xml: session-start/metadata.xml::alter_session_start::Ebix: Computed checksum for inputStream as d2a9c9002a66f9fe4e8c4aa41810b63c

v4.17.2 output:
[2023-02-14 22:01:01] INFO [liquibase.lockservice] Successfully acquired change log lock
[2023-02-14 22:01:08] INFO [liquibase.changelog] Reading from TPPONPREMDEV.DATABASECHANGELOG
[2023-02-14 22:11:17] INFO [liquibase.lockservice] Successfully released change log lock
Liquibase command 'update' was executed successfully.

Additional Context

Add any other context about the problem here.

[ligenzatomas]

I am experiencing the same problem with Postgres database and Liquibase version 4.18.0 on localhost (Docker container) and also in cloud environment (Bitbucket pipeline default runner).

There is a part of log output:
2023-02-15 16:00:27.596 INFO 1141727 --- [nio-8088-exec-1] liquibase.lockservice : Successfully acquired change log lock
2023-02-15 16:00:27.985 INFO 1141727 --- [nio-8088-exec-1] liquibase.changelog : Reading from assets.databasechangelog
Running Changeset: app.xml::2021-09-02_pze::tomas.marek
2023-02-15 16:08:39.899 INFO 1141727 --- [nio-8088-exec-1] liquibase.changelog : SQL in file 2021-09-02_pze.sql executed
2023-02-15 16:08:39.900 INFO 1141727 --- [nio-8088-exec-1] liquibase.changelog : ChangeSet app.xml::2021-09-02_pze::tomas.marek ran successfully in 18ms

[nvoxland]

We have been working on performance improvements over the last couple releases, including 4.19.0 and 4.19.1 which should come out next week.

Would you be able to run liquibase with the --monitor-performance=true flag set and send the generated .jfr file to me at nathan@liquibase.org? That will help me see for sure where the slowness is coming from.

[doakd]

@nvoxland,

I sent the .jfr via email. Thanks!

[doakd]

@nvoxland

I sent a new zipped version of the file via email. thanks!

[nvoxland]

I was able to get the new jfr file to load, @doakd. Thanks!

It looks like the time is primarily spent in DatabaseChangelog.normalizePath()'s replaceAll() calls. There was a performance fix in 4.15.0 in this method with #3063 but it looks like there is more to do with it. I'd guess calls to that method need to be combined/cached/removed vs. just optimizing the call itself. We could also replace some (or all?) of the regexp replacements with a more simple char replacement which will perform a lot better given that this is a commonly called function.

The performance is likely getting worse based on the number of changesets in your databasechangelog file (including any included files). Do you have a general count of what you have for reference?

[doakd]

@nvoxland Unfortunately the zip was removed from the email by my company. I replied to your email also.

There are 1774 changesets in the databasechangelog table.
There are 114 preconditions.
There are 2 runAlways changesets.

The current folder structure looks like this:

master.xml
   include folder1/update.xml
       include folder1/foldera/metadata.xml
           multiple changelogs
       include folder1/folderb/tables.xml
           multiple changelogs
       include folder1/folderc/views.xml
           multiple changelogs
   include folder2/update.xml
       include folder2/foldera/metadata.xml
           multiple changelogs
   include folder3/update.xml
       include folder3/foldera/tables.xml
           multiple changelogs
       include folder3/folderb/views.xml
           multiple changelogs
.
.
.
   include folder112/update.xml
       include folder112/foldera/metadata.xml
           multiple changelogs
       include folder112/folderb/tables.xml
           multiple changelogs
       include folder112/folderc/views.xml
           multiple changelogs

There are 389 total folders: 112 folders with 277 subfolders. They add new folders for each deployment.
There are 980 files total.

Hope this makes sense.

[doakd]

@nvoxland
I downloaded the new jar and ran a test using update-sql. It's not exactly apples to apples since I had to run this locally from my windows laptop, instead of inside of our docker container, but hopefully this helps. It took about 4 minutes, instead of 10 minutes, so a bit of an improvement.

Starting Liquibase at 06:53:31 (version [Core: //normalizePath-performance/7520/670753/2023-02-22 16:59+0000, Pro: master/2787/e6eff1/2023-02-20T17:19:52Z] #7520 built at 2023-02-22 16:59+0000)
Liquibase Version: [Core: //normalizePath-performance/7520/670753/2023-02-22 16:59+0000, Pro: master/2787/e6eff1/2023-02-20T17:19:52Z]
Liquibase Open Source [Core: //normalizePath-performance/7520/670753/2023-02-22 16:59+0000, Pro: master/2787/e6eff1/2023-02-20T17:19:52Z] by Liquibase
[2023-02-23 06:53:39] INFO [liquibase.changelog] Reading from TPPONPREMDEV.DATABASECHANGELOG
[2023-02-23 06:57:57] SEVERE [liquibase.integration] Validation Failed:

[nvoxland]

Thanks @doakd . It looks like the validation failed and execution stopped vs. correctly generating the SQL?

Could you send me the complete log (especially the validation failed error and stacktrace) and a new --monitor-performance output?

[doakd]

@nvoxland

I sent the new jfr and output via email. The changelogs unfortunately have some validation issues that I can't correct. Hopefully that not an issue. If it is I'll work with the developer to see how I can get a clean test.

Thanks.

[nvoxland]

@doakd

I wouldn't think #3853 would impact validation, but sometimes there unexpected results. If you are seeing the validation errors only with the snapshot jar, let me know and I can help look into it.

The new profile report has the remaining spent time solidly in the "compute the checksums for sql changes". I think that will be addressed with #3616 which will hopefully be merged soon. That PR does makes a variety of changes to the checksum calculation logic, including a significant streamlining of the checksum logic for sql changes. Its enough of a change that we upgrade the "checksum version" which makes swapping between versions a bit odd, and it won't have the change from #3853 in it, so it's hard to get you a build with those two changes in there. Based on your performance log, though, I think it should resolve most of the remaining slowness.

[doakd]

@nvoxland

Yes it turns out that only the new version gets the validation error. I'll let the customer know that a potential fix is coming soon.

Thanks.

[nvoxland]

Can you list what the validation error is? Is it a "duplicate changeset" error" Or something else?

[doakd]

@nvoxland

I resolved the validation issue, and sent you an updated log and jfr via email.

Read time is at 13 minutes.

[doakd]

@nvoxland

Yes, the validation error was a duplicate changeset.

Just ran update-sql again on 4.17.2, took a little less than 10 minutes:

[2023-02-27 23:21:41] INFO [liquibase.changelog] Reading from TPPONPREMDEV.DATABASECHANGELOG
[2023-02-27 23:31:10] INFO [liquibase.changelog] SQL in file 02_V_GETTPPPOLICYDETAILS.sql executed

[filipelautert]

Hello @doakd , I'll work with Nathan on this one. You mentioned that "Read time is at 13 minutes." - is this with the latest perfomance improvements from #3853 ?

[doakd]

I don't know the issue numbers that were in the jar that @nvoxland had me download.

[filipelautert]

Hello @doakd - would you be able to run a test using Liquibase 4.16.1 ? We had some breaking changes on 4.17.0 and I believe it may be related to this problem, but would like to confirm that.

[doakd]

@filipelautert You are correct, works fine in v4.16.1:

Starting Liquibase at 09:45:35 (version 4.16.1 #4594 built at 2022-09-14 15:27+0000)
Liquibase Version: 4.16.1
Liquibase Community 4.16.1 by Liquibase
Saving performance data to C:\users\doakd\downloads\liquibase-4.16.1\liquibase-2023_03_13T09_45_35_792.jfr
[2023-03-13 09:45:41] INFO [liquibase.lockservice] Successfully acquired change log lock
[2023-03-13 09:46:09] INFO [liquibase.changelog] Reading from TPPONPREMDEV.DATABASECHANGELOG
[2023-03-13 09:46:38] INFO [liquibase.lockservice] Successfully released change log lock

[filipelautert]

Hello @doakd - do you mind running 4.20.0 it in debug (--log-level=debug) and send me the results at ... ? Then we can take from there.

[doakd]

@filipelautert I ran v4.20.0, it's back to 13 minutes, and all of the time was spent on computing checksums, like this:

[2023-03-14 11:17:50] FINE [liquibase.util] Computed checksum for inputStream as b2abdd9fa353eb4ec5d250a84a9b4d1d
[2023-03-14 11:17:50] FINE [liquibase.util] Computed checksum for 8:b2abdd9fa353eb4ec5d250a84a9b4d1d: as e37347b1b53a396d8ee5dabcb626af24

I reran v4.16.1 with debug, the compute checksum step took 35 seconds for the exact same files.

[doakd]

@filipelautert Can you tell me what the next steps are on this?

[filipelautert]

Hello @doakd - PR #3853 was merged to master. You can get the jar here -> https://github.com/liquibase/liquibase/suites/11640405747/artifacts/604371760 .

Can you use it and check if there are any changes? Also can you send me the jfr file at flautert@liquibase.org ?

[doakd]

@filipelautert I'm getting a 404 when I try to follow that link.

[filipelautert]

Hello @doakd - this is the updated link: https://github.com/liquibase/liquibase/suites/11771216072/artifacts/613789067

[doakd]

@filipelautert I don't know what to do with all of the files in that zip. I'm not a java programmer, I'm just an Oracle DBA. LOL

[filipelautert]

haha no problems @doakd ! Inside the zip file you may find liquibase-core-0-SNAPSHOT.jar . Just replace the liquibase-core.jar that you are using with this one and you'll be able to test it.

[doakd]

@filipelautert Still took 11 minutes. files sent via email.

[doakd]

@filipelautert I replied to your email that I was not able to download using the link you provided.

[doakd]

Starting Liquibase at 09:31:18 (version [Core: //DAT-13285/8989/b241e5/2023-04-11 20:37+0000, Pro: master/2922/ef3bc8/2023-03-07T16:20:38Z] #8989 built at 2023-04-11 20:37+0000)
[2023-04-12 09:31:18] INFO [liquibase.ui] Starting Liquibase at 09:31:18 (version [Core: //DAT-13285/8989/b241e5/2023-04-11 20:37+0000, Pro: master/2922/ef3bc8/2023-03-07T16:20:38Z] #8989 built at 2023-04-11 20:37+0000)
Liquibase Version: [Core: //DAT-13285/8989/b241e5/2023-04-11 20:37+0000, Pro: master/2922/ef3bc8/2023-03-07T16:20:38Z]
[2023-04-12 09:31:18] INFO [liquibase.ui] Liquibase Version: [Core: //DAT-13285/8989/b241e5/2023-04-11 20:37+0000, Pro: master/2922/ef3bc8/2023-03-07T16:20:38Z]
Liquibase Open Source [Core: //DAT-13285/8989/b241e5/2023-04-11 20:37+0000, Pro: master/2922/ef3bc8/2023-03-07T16:20:38Z] by Liquibase
[2023-04-12 09:31:18] INFO [liquibase.ui] Liquibase Open Source [Core: //DAT-13285/8989/b241e5/2023-04-11 20:37+0000, Pro: master/2922/ef3bc8/2023-03-07T16:20:38Z] by Liquibase
Saving performance data to C:\users\xxx\downloads\liquibase-4.20.0\liquibase-2023_04_12T09_31_18_151.jfr
[2023-04-12 09:31:19] INFO [liquibase.ui] Saving performance data to C:\users\xxx\downloads\liquibase-4.20.0\liquibase-2023_04_12T09_31_18_151.jfr
[2023-04-12 09:31:19] INFO [liquibase.integration] Starting command execution.
[2023-04-12 09:31:23] INFO [liquibase.lockservice] Successfully acquired change log lock
[2023-04-12 09:31:38] INFO [liquibase.changelog] Reading from TPPONPREMDEV.DATABASECHANGELOG
[2023-04-12 09:46:23] INFO [liquibase.changelog] Reading from TPPONPREMDEV.DATABASECHANGELOG
[2023-04-12 09:46:39] INFO [liquibase.command] Using deploymentId: 1317983358
[2023-04-12 09:46:39] INFO [liquibase.changelog] Reading from TPPONPREMDEV.DATABASECHANGELOG
[2023-04-12 09:46:55] INFO [liquibase.changelog] SQL in file 02_V_GETTPPPOLICYDETAILS.sql executed
[2023-04-12 09:46:56] INFO [liquibase.changelog] ChangeSet tpp-14.10.1/03_View/views.xml::02_V_GETTPPPOLICYDETAILS_EBIX01S::Ebix ran successfully in 180ms
[2023-04-12 09:46:56] INFO [liquibase.changelog] SQL in file 02_V_GETTPPPOLICYDETAILS.sql executed
[2023-04-12 09:46:56] INFO [liquibase.changelog] ChangeSet tpp-14.10.1/03_View/views.xml::02_V_GETTPPPOLICYDETAILS_EBIX01T::Ebix ran successfully in 171ms
[2023-04-12 09:46:56] INFO [liquibase.changelog] SQL in file 02_V_GETTPPPOLICYDETAILS.sql executed
[2023-04-12 09:46:56] INFO [liquibase.changelog] ChangeSet tpp-14.10.1/03_View/views.xml::02_V_GETTPPPOLICYDETAILS_EBIX02U::Ebix ran successfully in 169ms
[2023-04-12 09:46:57] INFO [liquibase.changelog] SQL in file 02_V_GETTPPPOLICYDETAILS.sql executed
[2023-04-12 09:46:57] INFO [liquibase.changelog] ChangeSet tpp-14.10.1/03_View/views.xml::02_V_GETTPPPOLICYDETAILS_EBIX2X::Ebix ran successfully in 169ms
[2023-04-12 09:46:57] INFO [liquibase.changelog] SQL in file 02_V_GETTPPPOLICYDETAILS.sql executed
[2023-04-12 09:46:57] INFO [liquibase.changelog] ChangeSet tpp-14.10.1/03_View/views.xml::02_V_GETTPPPOLICYDETAILS_EBIX01B::Ebix ran successfully in 167ms
[2023-04-12 09:46:57] INFO [liquibase.changelog] SQL in file 02_V_GETTPPPOLICYDETAILS.sql executed
[2023-04-12 09:46:57] INFO [liquibase.changelog] ChangeSet tpp-14.10.1/03_View/views.xml::02_V_GETTPPPOLICYDETAILS_EBIX01D::Ebix ran successfully in 164ms
[2023-04-12 09:46:58] INFO [liquibase.command] Update command completed successfully.
[2023-04-12 09:46:58] INFO [liquibase.lockservice] Successfully released change log lock
[2023-04-12 09:46:58] INFO [liquibase.lockservice] Successfully released change log lock
[2023-04-12 09:46:58] INFO [liquibase.command] Command execution complete
Liquibase command 'update-sql' was executed successfully.

[Dasiu]

I experience similar situation to the one described by doakd. I can only provide partial data but maybe it will be useful.

• Migration using 3.6.3 takes ~2 min.
• The same migration using 4.20.0 takes ~15 minutes. Significant time (based on cyclic thread dumps) was spent around regexp - I think that has been fixed.
• The same migration using 4.21.1 takes ~15 minutes still. The change is this time significant time was spent in

app//liquibase.lockservice.StandardLockService.waitForLock(StandardLockService.java:258)
app//liquibase.command.core.helpers.LockServiceCommandStep.run(LockServiceCommandStep.java:38)
app//liquibase.command.CommandScope.execute(CommandScope.java:212)
app//liquibase.Liquibase.lambda$update$0(Liquibase.java:237)
app//liquibase.Liquibase$$Lambda$373/0x000000080122e948.run(Unknown Source)
app//liquibase.Scope.lambda$child$0(Scope.java:194)
app//liquibase.Scope$$Lambda$374/0x000000080122ed70.run(Unknown Source)
app//liquibase.Scope.child(Scope.java:203)
app//liquibase.Scope.child(Scope.java:193)
app//liquibase.Scope.child(Scope.java:172)
app//liquibase.Liquibase.runInScope(Liquibase.java:1618)
app//liquibase.Liquibase.update(Liquibase.java:229)
app//liquibase.Liquibase.update(Liquibase.java:213)
app//liquibase.Liquibase.update(Liquibase.java:198)

In my setup, I spawn multiple Liquibase instances and migrate multiple hosts in parallel.

[doakd]

just upgraded to v4.21.1, same problem exists. 10 minutes reading changelog:

Starting Liquibase at 17:25:49 (version 4.21.1 #9070 built at 2023-04-13 20:56+0000)
[2023-05-02 17:25:49] INFO [liquibase.ui] Starting Liquibase at 17:25:49 (version 4.21.1 #9070 built at 2023-04-13 20:56+0000)
Liquibase Version: 4.21.1
[2023-05-02 17:25:49] INFO [liquibase.ui] Liquibase Version: 4.21.1
Liquibase Open Source 4.21.1 by Liquibase
[2023-05-02 17:25:49] INFO [liquibase.ui] Liquibase Open Source 4.21.1 by Liquibase
[2023-05-02 17:25:49] INFO [liquibase.integration] Starting command execution.
[2023-05-02 17:25:50] INFO [liquibase.lockservice] Successfully acquired change log lock
[2023-05-02 17:25:58] INFO [liquibase.changelog] Reading from NWEBIXTP.DATABASECHANGELOG
[2023-05-02 17:36:00] INFO [liquibase.command] Using deploymentId: 3048359762

UPDATE SUMMARY
Run: 33
Previously run: 1264
Filtered out: 0

Total change sets: 1297

[rafaelsms]

I also encountered this issue: we had updated liquibase-core to the latest version, 4.23.0, but had to downgrade because the performance regression was very significant. We found that this issue started between v3.6.3 and v3.7.0

[doakd]

Upgraded to Liquibase 4.23.1, still having the issue:

Starting Liquibase at 19:28:00 (version 4.23.1 #12042 built at 2023-08-10 13:48+0000)
[2023-09-01 19:28:00] INFO [liquibase.ui] Starting Liquibase at 19:28:00 (version 4.23.1 #12042 built at 2023-08-10 13:48+0000)
Liquibase Version: 4.23.1
[2023-09-01 19:28:00] INFO [liquibase.ui] Liquibase Version: 4.23.1
Liquibase Open Source 4.23.1 by Liquibase
[2023-09-01 19:28:00] INFO [liquibase.ui] Liquibase Open Source 4.23.1 by Liquibase
[2023-09-01 19:28:00] INFO [liquibase.integration] Starting command execution.
[2023-09-01 19:28:23] INFO [liquibase.changelog] Reading from NWEBIXTP.DATABASECHANGELOG
[2023-09-01 19:39:00] INFO [liquibase.lockservice] Successfully acquired change log lock
[2023-09-01 19:39:01] INFO [liquibase.command] Using deploymentId: 3597141795
.
.
.
UPDATE SUMMARY
Run: 106
Previously run: 1750
Filtered out: 0

Total change sets: 1856

[2023-09-01 19:40:37] INFO [liquibase.util] Update summary generated
[2023-09-01 19:40:37] INFO [liquibase.command] Update command completed successfully.
Liquibase: Update has been successful. Rows affected: 2976
[2023-09-01 19:40:37] INFO [liquibase.ui] Liquibase: Update has been successful. Rows affected: 2976
[2023-09-01 19:40:37] INFO [liquibase.lockservice] Successfully released change log lock
[2023-09-01 19:40:37] INFO [liquibase.command] Command execution complete
Liquibase command 'update' was executed successfully.
[2023-09-01 19:40:37] INFO [liquibase.ui] Liquibase command 'update' was executed successfully.

[filipelautert]

@rafaelsms - your problem may be related to #4957 .
UPDATE: or not, just noticed the comment about 3.7.0

[filipelautert]

Hi @doakd - liquibase 4.25.0 seems to have fixed performance issues for some people (as mentioned here) and the next release (4.26.0) will bring another performance fix too. Could you give a try on 4.25.0 and see if it improved for you too?
Thanks!

[doakd]

@filipelautert Thanks for the update. I can confirm it is fixed.