liquibase: Liquibase is very slow on startup with spring boot
Environment
Liquibase Version: 3.8.5 Liquibase Integration & Version: spring boot Liquibase Extension(s) & Version: none Database Vendor & Version: oracle v12 Operating System Type & Version: unix rhel v7
Description
Hello Sometime Liquibase can take a lot of time to startup ~3 minutes without any changelog to apply. I don’t know why, and the problem didn’t occurred with the last version i used 3.6.3. I run Liquibase in spring boot applications.
Steps To Reproduce
I don’t know how to reproduce it. It appends randomly
Screenshots (if appropriate)
2020-08-09 06:40:16.956 [main] INFO o.h.annotations.common.Version.<clinit> - HCANN000001: Hibernate Commons Annotations {5.1.0.Final}
2020-08-09 06:40:16.763 [main] INFO org.hibernate.Version.logVersion - HHH000412: Hibernate Core {5.4.10.Final}
2020-08-09 06:40:16.677 [main] INFO o.h.jpa.internal.util.LogHelper.logPersistenceUnitInformation - HHH000204: Processing PersistenceUnitInfo [name: default]
2020-08-09 06:40:16.558 [main] INFO l.lockservice.StandardLockService.info - Successfully released change log lock
2020-08-09 06:40:16.493 [main] INFO liquibase.executor.jvm.JdbcExecutor.info - SELECT * FROM DATABASECHANGELOG ORDER BY DATEEXECUTED ASC, ORDEREXECUTED ASC
2020-08-09 06:40:16.492 [main] INFO l.c.StandardChangeLogHistoryService.info - Reading from DATABASECHANGELOG
2020-08-09 06:40:16.491 [main] INFO liquibase.executor.jvm.JdbcExecutor.info - SELECT COUNT(*) FROM DATABASECHANGELOG
2020-08-09 06:40:16.483 [main] INFO liquibase.executor.jvm.JdbcExecutor.info - SELECT MD5SUM FROM DATABASECHANGELOG WHERE MD5SUM IS NOT NULL AND ROWNUM=1
2020-08-09 06:35:51.224 [main] INFO l.lockservice.StandardLockService.info - Successfully acquired change log lock
2020-08-09 06:35:51.207 [main] INFO liquibase.executor.jvm.JdbcExecutor.info - SELECT LOCKED FROM DATABASECHANGELOGLOCK WHERE ID=1 FOR UPDATE
2020-08-09 06:35:51.205 [main] INFO liquibase.executor.jvm.JdbcExecutor.info - SELECT COUNT(*) FROM DATABASECHANGELOGLOCK
2020-08-09 06:35:51.198 [main] INFO liquibase.executor.jvm.JdbcExecutor.info - SELECT COUNT(*) FROM DATABASECHANGELOGLOCK
2020-08-09 06:35:50.684 [main] INFO l.database.core.OracleDatabase.info - Could not set remarks reporting on OracleDatabase: com.zaxxer.hikari.pool.HikariProxyConnection.setRemarksReporting(boolean)
About this issue
- Original URL
- State: closed
- Created 4 years ago
- Reactions: 11
- Comments: 30 (9 by maintainers)
After investigation with my DBAs, we found that after 3.6.3, liquibase executes this query 9 times:
When the parsing of this query is not in cache, Oracle will find 5 executions plans (18,5 seconds each plan = 1minutes 30 secondes) When the parsing is in cache, Oracle will use only one and unique execution plan. Results are immediates.
We use a standard edition without any customization
@rs-dpatil I am so glad!!! There is a security fix in 4.8 so it’s good to start using at least that for that reason as well. I am going to close this issue, but please reach out if you need anything else.
#2190 won’t help with this, I think.
The problem you seem to have here is that the way that Liquibase is checking that the DATABASECHANGELOG table exists and has the correct columns is very slow on your Oracle (the “createSnapshot” code).
#2190 will still do most of this work, as
checkLiquibaseTables
is on by default. That PR will stop Liquibase from taking a “lock” in some cases, which is independent of the problem here.I think the correct fix here is one of these two:
a) Determine if there is a faster way of inspecting the schema of a table in Oracle than the current approach and use it if so. Your idea to use
USER_ *
rather thanall_tab_cols
sounds promising. You will need to take care that any changes don’t break other users of Oracle who may have different schema setups.b) Double check whether Liquibase really needs to inspect the schema in this way, and consider simplifying the startup process to skip that, if it does not. This will require a bit more thought and investigation than (a), but may be a better end result. It seems to me that, if the goal is to handle schema mismatch in the Liquibase tables (DATABASECHANGELOG and others), perhaps we should just do a “SELECT” and handle errors + check the shape of the results, rather than inspecting the meta tables. If the Liquibase tables are not in the shape we expect, we will get a “no such column” error from the db, and can handle that.
(It is a bit surprising to me that Oracle will take so long just to tell you what columns are in its tables.)
GL
Hi @callain . Thanks for the excellent review. I’ll get with the team and follow up with more info.
After doing some investigations, it seems that everything starts with this part of code.
StandardChangeLogHistoryService.java
It get to this part in DatabaseSnapshot
This is where it executes this SQL query as much as there are columns in the DATABASECHANGELOG table.
I can reproduces it every time if I clean the sharedPool and the bufferCache before starting the app
What I understand is liquibase need to check the confirmity of the DATABASECHANGELOG table in a generic way. You are doing this using a
Snapshot
concept I don’t understand yet. Looping on all DATABASECHANGELOG columns somewhere, but why ?