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)

Most upvoted comments

After investigation with my DBAs, we found that after 3.6.3, liquibase executes this query 9 times:

SELECT  NULL AS TABLE_CAT, atc.OWNER AS TABLE_SCHEMA, atc.OWNER, 
  atc.TABLE_NAME, atc.COLUMN_NAME, NULLABLE, ac.VALIDATED as VALIDATED, 
  ac.SEARCH_CONDITION, ac.CONSTRAINT_NAME 
FROM
 ALL_TAB_COLS atc JOIN all_cons_columns acc ON atc.OWNER = acc.OWNER AND 
  atc.TABLE_NAME = acc.TABLE_NAME AND atc.COLUMN_NAME = acc.COLUMN_NAME JOIN 
  all_constraints ac ON atc.OWNER = ac.OWNER AND atc.TABLE_NAME = 
  ac.TABLE_NAME AND acc.CONSTRAINT_NAME = ac.CONSTRAINT_NAME  WHERE atc.OWNER=
  'MY_SCHEMA' AND atc.hidden_column='NO' AND ac.CONSTRAINT_TYPE='C'  and 
  ac.search_condition is not null  AND atc.TABLE_NAME='DATABASECHANGELOG'

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 than all_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

        Table changeLogTable = null;
        try {
            changeLogTable = SnapshotGeneratorFactory.getInstance().getDatabaseChangeLogTable(new SnapshotControl
                (database, false, Table.class, Column.class), database);
        } catch (LiquibaseException e) {
            throw new UnexpectedLiquibaseException(e);
        }

It get to this part in DatabaseSnapshot

T object = chain.snapshot(example, this);

This is where it executes this SQL query as much as there are columns in the DATABASECHANGELOG table.

SELECT
    NULL            AS table_cat,
    atc.owner       AS table_schema,
    atc.owner,
    atc.table_name,
    atc.column_name,
    nullable,
    ac.validated    AS validated,
    ac.search_condition,
    ac.constraint_name
FROM
         all_tab_cols atc
    JOIN all_cons_columns  acc ON atc.owner = acc.owner
                                 AND atc.table_name = acc.table_name
                                 AND atc.column_name = acc.column_name
    JOIN all_constraints   ac ON atc.owner = ac.owner
                               AND atc.table_name = ac.table_name
                               AND acc.constraint_name = ac.constraint_name
WHERE
        atc.owner = 'MY_SCHEMA'
    AND atc.hidden_column = 'NO'
    AND ac.constraint_type = 'C'
    AND ac.search_condition IS NOT NULL
    AND atc.table_name = 'DATABASECHANGELOG'

I can reproduces it every time if I clean the sharedPool and the bufferCache before starting the app

ALTER SYSTEM FLUSH SHARED_POOL;
ALTER SYSTEM FLUSH BUFFER_CACHE;

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 ?