In memory DB deadlock with MVCC
"Lichota, Lukasz" <[email protected]>
| Newsgroups | gmane.comp.java.hsqldb.user |
|---|---|
| Message-ID | <B56EB3AE9A53784AAA7C4E9E22D1FBDA2649840E96@SGLONMMP001.Global.ad.sabre.com> |
Hi,
I have a set of flyway migration scripts which are applied to in memory HSQL DB in junit test.
After I change transaction control to MVCC, any subsequent DDL statement causes DB to hang.
E.g. this hangs on migration x+1:
Migration X:
SET DATABASE TRANSACTION CONTROL MVCC;
Migration X+1
CREATE TABLE test (id BIGINT NOT NULL);
When I use LOCKS then it works ok, so this doesn't hang:
Migration X:
SET DATABASE TRANSACTION CONTROL LOCKS;
Migration X+1
CREATE TABLE test (id BIGINT NOT NULL);
I checked threads and there one thread waiting on latch as below and no other thread that would release this latch so it's final deadlock.
Thread [main] (Suspended)
Unsafe.park(boolean, long) line: not available [native method]
LockSupport.park(Object) line: 186
CountDownLatch$Sync(AbstractQueuedSynchronizer).parkAndCheckInterrupt() line: 834
CountDownLatch$Sync(AbstractQueuedSynchronizer).doAcquireSharedInterruptibly(int) line: 994
CountDownLatch$Sync(AbstractQueuedSynchronizer).acquireSharedInterruptibly(int) line: 1303
CountDownLatch.await() line: 236 [local variables unavailable]
CountUpDownLatch.await() line: not available [local variables unavailable]
Session.executeCompiledStatement(Statement, Object[], int) line: 1318
Session.executeDirectStatement(Result) line: not available
Session.execute(Result) line: not available
JDBCStatement.fetchResult(String, int, int, int[], String[]) line: not available
JDBCStatement.execute(String) line: not available
StatementSpy.execute(String) line: 839
DbMigrator$2(JdbcTemplate).executeStatement(String) line: 243
SqlStatement.execute(JdbcTemplate) line: 77
HsqlSqlScript(SqlScript).execute(JdbcTemplate) line: 91
SqlMigration.migrate(JdbcTemplate, DbSupport) line: 83
DbMigrator$3.doInTransaction() line: 221
DbMigrator$3.doInTransaction() line: 218
TransactionTemplate.execute(TransactionCallback<T>) line: 54
DbMigrator.applyMigration(Migration) line: 218
DbMigrator.access$400(DbMigrator, Migration) line: 42
DbMigrator$1.doInTransaction() line: 149
DbMigrator$1.doInTransaction() line: 114
TransactionTemplate.execute(TransactionCallback<T>) line: 54
DbMigrator.migrate(List<Migration>) line: 113
Flyway$1.execute(Connection, Connection, DbSupport) line: 608
Flyway$1.execute(Connection, Connection, DbSupport) line: 591
Flyway.execute(Command<T>) line: 882
Flyway.migrate() line: 591
...
Do you think that could be bad use of HSQL by flyway or my bad use of flyway? I also wonder why this latch.await doesn't use timeout? Any reason?
I read here (http://thread.gmane.org/gmane.comp.java.hsqldb.user/6152) that " With MVCC the database needs to be locked before the schema can be modified. Each SELECT or data change statement starts a transaction that needs to be committed."
I analyzed logs and it looks that flyway does each migration in separated transaction so I have migration X committed. Then flyway sets autocommitt=false and does some selects before running the next migration. So do I understand correctly that any DDL will never work with flyway and MVCC because of that? If autocommitt is false then the transactions of selects won't be committed before DDL statement (of the migration itself) so HSQL will wait forever. Do I understand correctly? Is there anything I can do?
I'm attaching these logs starting from the migration X commit just for reference.
2013-08-22 17:53:58,660 [main] DEBUG jdbc.audit - 1. Connection.commit() returned com.googlecode.flyway.core.util.jdbc.TransactionTemplate.execute(TransactionTemplate.java:55)
2013-08-22 17:53:58,660 [main] DEBUG jdbc.audit - 1. Connection.setAutoCommit(false) returned com.googlecode.flyway.core.util.jdbc.TransactionTemplate.execute(TransactionTemplate.java:53)
2013-08-22 17:53:58,661 [main] DEBUG jdbc.audit - 1. Connection.getMetaData() returned org.hsqldb.jdbc.JDBCDatabaseMetaData@1a5c091f com.googlecode.flyway.core.util.jdbc.JdbcTemplate.hasTables(JdbcTemplate.java:207)
2013-08-22 17:53:58,664 [main] DEBUG jdbc.audit - 1. PreparedStatement.new PreparedStatement returned com.googlecode.flyway.core.util.jdbc.JdbcTemplate.queryForInt(JdbcTemplate.java:132)
2013-08-22 17:53:58,664 [main] DEBUG jdbc.audit - 1. Connection.prepareStatement(SELECT COUNT(*) FROM PUBLIC.schema_version) returned net.sf.log4jdbc.PreparedStatementSpy@6738694b com.googlecode.flyway.core.util.jdbc.JdbcTemplate.queryForInt(JdbcTemplate.java:132)
2013-08-22 17:53:58,665 [main] DEBUG jdbc.sqlonly - com.googlecode.flyway.core.util.jdbc.JdbcTemplate.queryForInt(JdbcTemplate.java:136)
1. SELECT COUNT(*) FROM PUBLIC.schema_version
2013-08-22 17:53:58,665 [main] DEBUG jdbc.sqltiming - com.googlecode.flyway.core.util.jdbc.JdbcTemplate.queryForInt(JdbcTemplate.java:136)
1. SELECT COUNT(*) FROM PUBLIC.schema_version {executed in 0 msec}
2013-08-22 17:53:58,665 [main] DEBUG jdbc.resultset - 1. ResultSet.new ResultSet returned com.googlecode.flyway.core.util.jdbc.JdbcTemplate.queryForInt(JdbcTemplate.java:136)
2013-08-22 17:53:58,665 [main] DEBUG jdbc.audit - 1. PreparedStatement.executeQuery() returned net.sf.log4jdbc.ResultSetSpy@2888efde com.googlecode.flyway.core.util.jdbc.JdbcTemplate.queryForInt(JdbcTemplate.java:136)
2013-08-22 17:53:58,666 [main] DEBUG jdbc.resultset - 1. ResultSet.next() returned true com.googlecode.flyway.core.util.jdbc.JdbcTemplate.queryForInt(JdbcTemplate.java:137)
2013-08-22 17:53:58,666 [main] DEBUG jdbc.resultset - 1. ResultSet.getInt(1) returned 11 com.googlecode.flyway.core.util.jdbc.JdbcTemplate.queryForInt(JdbcTemplate.java:138)
2013-08-22 17:53:58,666 [main] DEBUG jdbc.resultset - 1. ResultSet.close() returned null com.googlecode.flyway.core.util.jdbc.JdbcUtils.closeResultSet(JdbcUtils.java:105)
2013-08-22 17:53:58,666 [main] DEBUG jdbc.audit - 1. PreparedStatement.close() returned com.googlecode.flyway.core.util.jdbc.JdbcUtils.closeStatement(JdbcUtils.java:88)
2013-08-22 17:53:58,666 [main] DEBUG jdbc.audit - 1. Statement.new Statement returned com.googlecode.flyway.core.util.jdbc.JdbcTemplate.query(JdbcTemplate.java:312)
2013-08-22 17:53:58,667 [main] DEBUG jdbc.audit - 1. Connection.createStatement() returned net.sf.log4jdbc.StatementSpy@363bec9c com.googlecode.flyway.core.util.jdbc.JdbcTemplate.query(JdbcTemplate.java:312)
2013-08-22 17:53:58,667 [main] DEBUG jdbc.sqlonly - com.googlecode.flyway.core.util.jdbc.JdbcTemplate.query(JdbcTemplate.java:313)
1. select version as VERSION, description as DESCRIPTION, type as TYPE, script as SCRIPT, checksum as CHECKSUM, installed_on as INSTALLED_ON, execution_time as EXECUTION_TIME, state as STATE from PUBLIC.schema_version where current_version=1
2013-08-22 17:53:58,669 [main] DEBUG jdbc.sqltiming - com.googlecode.flyway.core.util.jdbc.JdbcTemplate.query(JdbcTemplate.java:313)
1. select version as VERSION, description as DESCRIPTION, type as TYPE, script as SCRIPT, checksum as CHECKSUM, installed_on as INSTALLED_ON, execution_time as EXECUTION_TIME, state as STATE from PUBLIC.schema_version where current_version=1 {executed in 1 msec}
2013-08-22 17:53:58,669 [main] DEBUG jdbc.resultset - 1. ResultSet.new ResultSet returned com.googlecode.flyway.core.util.jdbc.JdbcTemplate.query(JdbcTemplate.java:313)
2013-08-22 17:53:58,669 [main] DEBUG jdbc.audit - 1. Statement.executeQuery(select version as VERSION, description as DESCRIPTION, type as TYPE, script as SCRIPT, checksum as CHECKSUM, installed_on as INSTALLED_ON, execution_time as EXECUTION_TIME, state as STATE from PUBLIC.schema_version where current_version=1) returned net.sf.log4jdbc.ResultSetSpy@338f5998 com.googlecode.flyway.core.util.jdbc.JdbcTemplate.query(JdbcTemplate.java:313)
2013-08-22 17:53:58,669 [main] DEBUG jdbc.resultset - 1. ResultSet.next() returned true com.googlecode.flyway.core.util.jdbc.JdbcTemplate.query(JdbcTemplate.java:316)
2013-08-22 17:53:58,670 [main] DEBUG jdbc.resultset - 1. ResultSet.getString(VERSION) returned 1.10 com.googlecode.flyway.core.metadatatable.MetaDataTable$MetaDataTableRowMapper.mapRow(MetaDataTable.java:286)
2013-08-22 17:53:58,670 [main] DEBUG jdbc.resultset - 1. ResultSet.getString(DESCRIPTION) returned set higher transaction isolation com.googlecode.flyway.core.metadatatable.MetaDataTable$MetaDataTableRowMapper.mapRow(MetaDataTable.java:287)
2013-08-22 17:53:58,670 [main] DEBUG jdbc.resultset - 1. ResultSet.getString(TYPE) returned SQL com.googlecode.flyway.core.metadatatable.MetaDataTable$MetaDataTableRowMapper.mapRow(MetaDataTable.java:288)
2013-08-22 17:53:58,671 [main] DEBUG jdbc.resultset - 1. ResultSet.getString(SCRIPT) returned V1_10__set_higher_transaction_isolation.sql com.googlecode.flyway.core.metadatatable.MetaDataTable$MetaDataTableRowMapper.mapRow(MetaDataTable.java:289)
2013-08-22 17:53:58,671 [main] DEBUG jdbc.resultset - 1. ResultSet.getObject(CHECKSUM) returned 1576730298 com.googlecode.flyway.core.metadatatable.MetaDataTable$MetaDataTableRowMapper.mapRow(MetaDataTable.java:290)
2013-08-22 17:53:58,672 [main] DEBUG jdbc.resultset - 1. ResultSet.getTimestamp(INSTALLED_ON) returned 2013-08-22 17:53:58.659 com.googlecode.flyway.core.metadatatable.MetaDataTable$MetaDataTableRowMapper.mapRow(MetaDataTable.java:291)
2013-08-22 17:53:58,672 [main] DEBUG jdbc.resultset - 1. ResultSet.getObject(EXECUTION_TIME) returned 6 com.googlecode.flyway.core.metadatatable.MetaDataTable$MetaDataTableRowMapper.mapRow(MetaDataTable.java:292)
2013-08-22 17:53:58,672 [main] DEBUG jdbc.resultset - 1. ResultSet.getString(STATE) returned SUCCESS com.googlecode.flyway.core.metadatatable.MetaDataTable$MetaDataTableRowMapper.mapRow(MetaDataTable.java:293)
2013-08-22 17:53:58,673 [main] INFO jdbc.resultsettable - |--------|---------------------------------|-----|--------------------------------------------|-----------|------------------------|---------------|--------|
2013-08-22 17:53:58,674 [main] INFO jdbc.resultsettable - |VERSION |DESCRIPTION |TYPE |SCRIPT |CHECKSUM |INSTALLED_ON |EXECUTION_TIME |STATE |
2013-08-22 17:53:58,674 [main] INFO jdbc.resultsettable - |--------|---------------------------------|-----|--------------------------------------------|-----------|------------------------|---------------|--------|
2013-08-22 17:53:58,675 [main] INFO jdbc.resultsettable - |1.10 |set higher transaction isolation |SQL |V1_10__set_higher_transaction_isolation.sql |1576730298 |2013-08-22 17:53:58.659 |6 |SUCCESS |
2013-08-22 17:53:58,675 [main] INFO jdbc.resultsettable - |--------|---------------------------------|-----|--------------------------------------------|-----------|------------------------|---------------|--------|
2013-08-22 17:53:58,676 [main] DEBUG jdbc.resultset - 1. ResultSet.next() returned false com.googlecode.flyway.core.util.jdbc.JdbcTemplate.query(JdbcTemplate.java:316)
2013-08-22 17:53:58,676 [main] DEBUG jdbc.resultset - 1. ResultSet.close() returned null com.googlecode.flyway.core.util.jdbc.JdbcUtils.closeResultSet(JdbcUtils.java:105)
2013-08-22 17:53:58,676 [main] DEBUG jdbc.audit - 1. Statement.close() returned com.googlecode.flyway.core.util.jdbc.JdbcUtils.closeStatement(JdbcUtils.java:88)
2013-08-22 17:53:58,676 [main] DEBUG jdbc.audit - 1. Connection.getMetaData() returned org.hsqldb.jdbc.JDBCDatabaseMetaData@843249a com.googlecode.flyway.core.util.jdbc.JdbcTemplate.hasTables(JdbcTemplate.java:207)
2013-08-22 17:53:58,678 [main] DEBUG jdbc.audit - 1. PreparedStatement.new PreparedStatement returned com.googlecode.flyway.core.util.jdbc.JdbcTemplate.queryForInt(JdbcTemplate.java:132)
2013-08-22 17:53:58,678 [main] DEBUG jdbc.audit - 1. Connection.prepareStatement(SELECT COUNT(*) FROM PUBLIC.schema_version) returned net.sf.log4jdbc.PreparedStatementSpy@dd5b524 com.googlecode.flyway.core.util.jdbc.JdbcTemplate.queryForInt(JdbcTemplate.java:132)
2013-08-22 17:53:58,678 [main] DEBUG jdbc.sqlonly - com.googlecode.flyway.core.util.jdbc.JdbcTemplate.queryForInt(JdbcTemplate.java:136)
1. SELECT COUNT(*) FROM PUBLIC.schema_version
2013-08-22 17:53:58,679 [main] DEBUG jdbc.sqltiming - com.googlecode.flyway.core.util.jdbc.JdbcTemplate.queryForInt(JdbcTemplate.java:136)
1. SELECT COUNT(*) FROM PUBLIC.schema_version {executed in 1 msec}
2013-08-22 17:53:58,679 [main] DEBUG jdbc.resultset - 1. ResultSet.new ResultSet returned com.googlecode.flyway.core.util.jdbc.JdbcTemplate.queryForInt(JdbcTemplate.java:136)
2013-08-22 17:53:58,679 [main] DEBUG jdbc.audit - 1. PreparedStatement.executeQuery() returned net.sf.log4jdbc.ResultSetSpy@49675594 com.googlecode.flyway.core.util.jdbc.JdbcTemplate.queryForInt(JdbcTemplate.java:136)
2013-08-22 17:53:58,680 [main] DEBUG jdbc.resultset - 1. ResultSet.next() returned true com.googlecode.flyway.core.util.jdbc.JdbcTemplate.queryForInt(JdbcTemplate.java:137)
2013-08-22 17:53:58,680 [main] DEBUG jdbc.resultset - 1. ResultSet.getInt(1) returned 11 com.googlecode.flyway.core.util.jdbc.JdbcTemplate.queryForInt(JdbcTemplate.java:138)
2013-08-22 17:53:58,680 [main] DEBUG jdbc.resultset - 1. ResultSet.close() returned null com.googlecode.flyway.core.util.jdbc.JdbcUtils.closeResultSet(JdbcUtils.java:105)
2013-08-22 17:53:58,680 [main] DEBUG jdbc.audit - 1. PreparedStatement.close() returned com.googlecode.flyway.core.util.jdbc.JdbcUtils.closeStatement(JdbcUtils.java:88)
2013-08-22 17:53:58,680 [main] DEBUG jdbc.audit - 1. Statement.new Statement returned com.googlecode.flyway.core.util.jdbc.JdbcTemplate.query(JdbcTemplate.java:312)
2013-08-22 17:53:58,681 [main] DEBUG jdbc.audit - 1. Connection.createStatement() returned net.sf.log4jdbc.StatementSpy@1f238d32 com.googlecode.flyway.core.util.jdbc.JdbcTemplate.query(JdbcTemplate.java:312)
2013-08-22 17:53:58,681 [main] DEBUG jdbc.sqlonly - com.googlecode.flyway.core.util.jdbc.JdbcTemplate.query(JdbcTemplate.java:313)
1. select version as VERSION, description as DESCRIPTION, type as TYPE, script as SCRIPT, checksum as CHECKSUM, installed_on as INSTALLED_ON, execution_time as EXECUTION_TIME, state as STATE from PUBLIC.schema_version where current_version=1
2013-08-22 17:53:58,682 [main] DEBUG jdbc.sqltiming - com.googlecode.flyway.core.util.jdbc.JdbcTemplate.query(JdbcTemplate.java:313)
1. select version as VERSION, description as DESCRIPTION, type as TYPE, script as SCRIPT, checksum as CHECKSUM, installed_on as INSTALLED_ON, execution_time as EXECUTION_TIME, state as STATE from PUBLIC.schema_version where current_version=1 {executed in 1 msec}
2013-08-22 17:53:58,682 [main] DEBUG jdbc.resultset - 1. ResultSet.new ResultSet returned com.googlecode.flyway.core.util.jdbc.JdbcTemplate.query(JdbcTemplate.java:313)
2013-08-22 17:53:58,682 [main] DEBUG jdbc.audit - 1. Statement.executeQuery(select version as VERSION, description as DESCRIPTION, type as TYPE, script as SCRIPT, checksum as CHECKSUM, installed_on as INSTALLED_ON, execution_time as EXECUTION_TIME, state as STATE from PUBLIC.schema_version where current_version=1) returned net.sf.log4jdbc.ResultSetSpy@a59cf7f com.googlecode.flyway.core.util.jdbc.JdbcTemplate.query(JdbcTemplate.java:313)
2013-08-22 17:53:58,682 [main] DEBUG jdbc.resultset - 1. ResultSet.next() returned true com.googlecode.flyway.core.util.jdbc.JdbcTemplate.query(JdbcTemplate.java:316)
2013-08-22 17:53:58,683 [main] DEBUG jdbc.resultset - 1. ResultSet.getString(VERSION) returned 1.10 com.googlecode.flyway.core.metadatatable.MetaDataTable$MetaDataTableRowMapper.mapRow(MetaDataTable.java:286)
2013-08-22 17:53:58,683 [main] DEBUG jdbc.resultset - 1. ResultSet.getString(DESCRIPTION) returned set higher transaction isolation com.googlecode.flyway.core.metadatatable.MetaDataTable$MetaDataTableRowMapper.mapRow(MetaDataTable.java:287)
2013-08-22 17:53:58,683 [main] DEBUG jdbc.resultset - 1. ResultSet.getString(TYPE) returned SQL com.googlecode.flyway.core.metadatatable.MetaDataTable$MetaDataTableRowMapper.mapRow(MetaDataTable.java:288)
2013-08-22 17:53:58,683 [main] DEBUG jdbc.resultset - 1. ResultSet.getString(SCRIPT) returned V1_10__set_higher_transaction_isolation.sql com.googlecode.flyway.core.metadatatable.MetaDataTable$MetaDataTableRowMapper.mapRow(MetaDataTable.java:289)
2013-08-22 17:53:58,684 [main] DEBUG jdbc.resultset - 1. ResultSet.getObject(CHECKSUM) returned 1576730298 com.googlecode.flyway.core.metadatatable.MetaDataTable$MetaDataTableRowMapper.mapRow(MetaDataTable.java:290)
2013-08-22 17:53:58,684 [main] DEBUG jdbc.resultset - 1. ResultSet.getTimestamp(INSTALLED_ON) returned 2013-08-22 17:53:58.659 com.googlecode.flyway.core.metadatatable.MetaDataTable$MetaDataTableRowMapper.mapRow(MetaDataTable.java:291)
2013-08-22 17:53:58,684 [main] DEBUG jdbc.resultset - 1. ResultSet.getObject(EXECUTION_TIME) returned 6 com.googlecode.flyway.core.metadatatable.MetaDataTable$MetaDataTableRowMapper.mapRow(MetaDataTable.java:292)
2013-08-22 17:53:58,685 [main] DEBUG jdbc.resultset - 1. ResultSet.getString(STATE) returned SUCCESS com.googlecode.flyway.core.metadatatable.MetaDataTable$MetaDataTableRowMapper.mapRow(MetaDataTable.java:293)
2013-08-22 17:53:58,686 [main] INFO jdbc.resultsettable - |--------|---------------------------------|-----|--------------------------------------------|-----------|------------------------|---------------|--------|
2013-08-22 17:53:58,686 [main] INFO jdbc.resultsettable - |VERSION |DESCRIPTION |TYPE |SCRIPT |CHECKSUM |INSTALLED_ON |EXECUTION_TIME |STATE |
2013-08-22 17:53:58,686 [main] INFO jdbc.resultsettable - |--------|---------------------------------|-----|--------------------------------------------|-----------|------------------------|---------------|--------|
2013-08-22 17:53:58,687 [main] INFO jdbc.resultsettable - |1.10 |set higher transaction isolation |SQL |V1_10__set_higher_transaction_isolation.sql |1576730298 |2013-08-22 17:53:58.659 |6 |SUCCESS |
2013-08-22 17:53:58,687 [main] INFO jdbc.resultsettable - |--------|---------------------------------|-----|--------------------------------------------|-----------|------------------------|---------------|--------|
2013-08-22 17:53:58,688 [main] DEBUG jdbc.resultset - 1. ResultSet.next() returned false com.googlecode.flyway.core.util.jdbc.JdbcTemplate.query(JdbcTemplate.java:316)
2013-08-22 17:53:58,688 [main] DEBUG jdbc.resultset - 1. ResultSet.close() returned null com.googlecode.flyway.core.util.jdbc.JdbcUtils.closeResultSet(JdbcUtils.java:105)
2013-08-22 17:53:58,688 [main] DEBUG jdbc.audit - 1. Statement.close() returned com.googlecode.flyway.core.util.jdbc.JdbcUtils.closeStatement(JdbcUtils.java:88)
2013-08-22 17:53:58,689 [main] INFO c.g.flyway.core.migration.DbMigrator - Migrating to version 1.11
2013-08-22 17:53:58,689 [main] DEBUG jdbc.audit - 2. Connection.setAutoCommit(false) returned com.googlecode.flyway.core.util.jdbc.TransactionTemplate.execute(TransactionTemplate.java:53)
2013-08-22 17:53:58,690 [main] DEBUG c.g.f.core.migration.sql.SqlScript - Found statement at line 1: create table test (id bigint not null);
2013-08-22 17:53:58,690 [main] DEBUG c.g.f.c.migration.sql.SqlStatement - Executing SQL: create table test (id bigint not null)
2013-08-22 17:53:58,691 [main] DEBUG jdbc.audit - 2. Statement.new Statement returned com.googlecode.flyway.core.util.jdbc.JdbcTemplate.executeStatement(JdbcTemplate.java:242)
2013-08-22 17:53:58,691 [main] DEBUG jdbc.audit - 2. Connection.createStatement() returned net.sf.log4jdbc.StatementSpy@7d15a969 com.googlecode.flyway.core.util.jdbc.JdbcTemplate.executeStatement(JdbcTemplate.java:242)
2013-08-22 17:53:58,691 [main] DEBUG jdbc.sqlonly - com.googlecode.flyway.core.util.jdbc.JdbcTemplate.executeStatement(JdbcTemplate.java:243)
2. create table test (id bigint not null)
//and now it hangs
------------------------------------------------------------------------------
Learn the latest--Visual Studio 2012, SharePoint 2013, SQL 2012, more!
Discover the easy way to master current and previous Microsoft technologies
and advance your career. Get an incredible 1,500+ hours of step-by-step
tutorial videos with LearnDevNow. Subscribe today and save!
http://pubads.g.doubleclick.net/gampad/clk?id=58040911&iu=/4140/ostg.clktrk
_______________________________________________
Hsqldb-user mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/hsqldb-user