Liquibase very slow and logging question

General Discussion
1

Hi,

I am using liquibase rc2-SNAPSHOT and am encountering 2 problems:

First, liquibase is very slow.

I have a small changeset which takes 7 (!!) seconds to finish (see logs below from 12:00:13 until 12:00:20).

Second, liquibase seems use different logging than my application, here is an example: (first an last line are from spring or my classes logs)

    mct 2010-06-10 12:00:13,762 INFO [com.xxx.core.jpa.liquibase.LiquibaseWrapper] - Initializing schema with context 'test' INFO 6/10/10 12:00 PM:liquibase: Successfully acquired change log lock INFO 6/10/10 12:00 PM:liquibase: Reading from domain.databasechangelog INFO 6/10/10 12:00 PM:liquibase: Change set classpath:META-INF/liquibase/domain/d-0001.xml::create-schema::rp failed, but failOnError was false.  Error: Error executing SQL create schema domain INFO 6/10/10 12:00 PM:liquibase: Successfully released change log lock mct 2010-06-10 12:00:20,145 INFO [org.springframework.context.support.GenericApplicationContext] - Bean 'liquibaseInitializer' is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)

Any help is welcome :slight_smile:

Thanx, Ron

2

How long a changeset takes to execute usually has a lot to do with what is in the changeset.  I haven’t gotten a chance to profile 2.0 lately, but plan to soon.  That may help too.

Liquibase uses java logging currently, which may be different than what you are using.  The logging framework is pluggable, so at some point I’ll document how there could be logging plugins that use different loggers (such as log4j)

Nathan

3

Thanx for the info Nathan,

Here is an example of how the peroformance of liquibase is actually impossible:

I have the following changesets:

http://www.liquibase.org/xml/ns/dbchangelog/1.9"   xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"   xsi:schemaLocation="http://www.liquibase.org/xml/ns/dbchangelog/1.9         http://www.liquibase.org/xml/ns/dbchangelog/dbchangelog-1.9.xsd">        

   

and

<?xml version="1.0" encoding="UTF-8"?> http://www.liquibase.org/xml/ns/dbchangelog/1.9"     xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"     xsi:schemaLocation="http://www.liquibase.org/xml/ns/dbchangelog/1.9         http://www.liquibase.org/xml/ns/dbchangelog/dbchangelog-1.9.xsd">        

   
    create schema media;
    drop schema media cascade;
   

   
       
   

These two take 5 (!) seconds to complete.
Here is the log output:

bws 17:13:18,306  INFO LiquibaseWrapper:36 - Initializing schema with context 'test' INFO 6/14/10 5:13 PM:liquibase: Successfully acquired change log lock INFO 6/14/10 5:13 PM:liquibase: classpath:META-INF/liquibase/media/mst-module.xml is using schema version 1.9 rather than version 2.0 INFO 6/14/10 5:13 PM:liquibase: classpath:META-INF/liquibase/media/md-0001.xml is using schema version 1.9 rather than version 2.0 INFO 6/14/10 5:13 PM:liquibase: Reading from media.databasechangelog INFO 6/14/10 5:13 PM:liquibase: Successfully released change log lock bws 17:13:23,580  INFO LiquibaseWrapper:51 - Creating schema 'shop'
4

Here’s some code that I use to redirect to SLF4J:

    package eg;

    import org.slf4j.Logger;
    import org.slf4j.LoggerFactory;

    import java.text.MessageFormat;
    import java.util.logging.*;

    /**

    private static final Logger log = LoggerFactory.getLogger(JuliToSlf4JHandler.class);

    private static boolean REDIRECTED = false;

    public enum LogLevel {
        OFF(Level.OFF.intValue()),
        ERROR(Level.SEVERE.intValue()),
        WARN(Level.WARNING.intValue()),
        INFO(Level.INFO.intValue()),
        DEBUG(Level.FINE.intValue()),
        TRACE(Level.FINER.intValue());

        private int juliPriority;

        LogLevel(int juliPriority) {
            this.juliPriority = juliPriority;
        }

        public static LogLevel toLogLevel(Level level) {
            int juliPriority = level.intValue();
            LogLevel[] levels = LogLevel.values();
            for (LogLevel logLevel : levels) {
                if (logLevel.juliPriority >= juliPriority)
                    return logLevel;
            }
            return OFF;
        }
    }

    /**
    * Globally redirects JULI to SLF4J.  This does nothing if it has already been
    * called once.
    */
    public static void redirect() {
        synchronized (JuliToSlf4JHandler.class) {
            if (REDIRECTED)
                return; // Already done.
            LogManager manager = LogManager.getLogManager();
            java.util.logging.Logger rootLogger = manager.getLogger("");
            redirect(rootLogger);
            REDIRECTED = true;
            log.info(“Java logging redirected to SLF4J”);
        }
    }

    public static void redirect(java.util.logging.Logger juliLogger) {
        JuliToSlf4JHandler newHandler = new JuliToSlf4JHandler();
        redirect(juliLogger, newHandler);
    }

    public static void redirect(java.util.logging.Logger juliLogger, Handler newHandler) {
        Handler[] handlers = juliLogger.getHandlers();
        for (Handler handler : handlers) {
            if (handler instanceof ConsoleHandler) {
                ConsoleHandler consoleHandler = (ConsoleHandler) handler;
                juliLogger.removeHandler(consoleHandler);
            }
            if (handler instanceof JuliToSlf4JHandler) {
                return; // Nothing to do.
            }
        }
        juliLogger.addHandler(newHandler);
    }

    public void publish(LogRecord record) {
        Logger slf4j = LoggerFactory.getLogger(record.getLoggerName());
        LogLevel level = LogLevel.toLogLevel(record.getLevel());
        publishToSlf4j(record, level, slf4j);
    }

    protected void publishToSlf4j(LogRecord record, LogLevel level, Logger slf4j) {
        switch (level) {
            case ERROR:
                if (slf4j.isErrorEnabled())
                    slf4j.error(toMessage(record));
                break;
            case WARN:
                if (slf4j.isWarnEnabled())
                    slf4j.warn(toMessage(record));
                break;
            case INFO:
                if (slf4j.isInfoEnabled())
                    slf4j.info(toMessage(record));
                break;
            case DEBUG:
                if (slf4j.isDebugEnabled())
                    slf4j.debug(toMessage(record));
                break;
            case TRACE:
                if (slf4j.isTraceEnabled())
                    slf4j.trace(toMessage(record));
                break;
            case OFF:
                break; // Do nothing, OFF means no logging.
        }
    }

    private String toMessage(LogRecord record) {
        String message = record.getMessage();
        // Format message
        try {
            Object parameters[] = record.getParameters();
            if (parameters != null && parameters.length != 0) {
                // Check for the first few parameters ?
                if (message.indexOf("{0}") >= 0 ||
                        message.indexOf("{1}") >= 0 ||
                        message.indexOf("{2}") >= 0 ||
                        message.indexOf("{3}") >= 0) {
                    message = MessageFormat.format(message, parameters);
                }
            }
        }
        catch (Exception ex) {
            // ignore Exception
        }
        return message;
    }

    @Override
    public void flush() {
        // nothing to do
    }

    @Override
    public void close() {
        // nothing to do
    }
}