Unit tests with in memory H2 db get terribly slow

Question

We have a large set of tests running against an in memory database. Each test creates its schema.

So far we were running those tests against a HSQL DB, but since H2 is supposed to be faster we tried switching to H2 instead.

When looking at the execution time H2 is actually significantly faster (10-50%). But when running lots of test H2 seems to take a break in between resulting in an overall performance much worse than HSQLDB (800-900%).

Any ideas how to keep the good performance of single tests for the full test suite?

These are the URLs we tried for H2:

jdbc:h2:mem:testdb
jdbc:h2:mem:testdb;DB_CLOSE_DELAY=-1
jdbc:h2:mem:testdb;MVCC=true
jdbc:h2:mem:testdb;DB_CLOSE_DELAY=-1;MODE=Oracle;MVCC=true

This is what we use with HSQL DB:

jdbc:hsqldb:mem:testdb

edit:

I tried to write a reprodocable test case but it's not so easy since we don't seem to have the problem when we only use simple jdbc. The tests get slow after approximately 500 tests that all use hibernate.

The only thing I noticed with VisualVM is that cpu usage is falling down close to zero with some noise the same time the tests start being slow.

edit 2:

JStack output:

2011-11-21 08:42:34
Full thread dump Java HotSpot(TM) Client VM (16.3-b01 mixed mode):

"ReaderThread" prio=6 tid=0x18e47400 nid=0x318 runnable [0x190ef000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.read(SocketInputStream.java:129)
    at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264)
    at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306)
    at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158)
    - locked <0x099d61c0> (a java.io.InputStreamReader)
    at java.io.InputStreamReader.read(InputStreamReader.java:167)
    at java.io.BufferedReader.fill(BufferedReader.java:136)
    at java.io.BufferedReader.readLine(BufferedReader.java:299)
    - locked <0x099d61c0> (a java.io.InputStreamReader)
    at java.io.BufferedReader.readLine(BufferedReader.java:362)
    at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner$ReaderThread.run(RemoteTestRunner.java:140)

   Locked ownable synchronizers:
    - None

"Low Memory Detector" daemon prio=6 tid=0x0244c400 nid=0x908 runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"CompilerThread0" daemon prio=10 tid=0x02447800 nid=0x10fc waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"Attach Listener" daemon prio=10 tid=0x02446400 nid=0x930 waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"Signal Dispatcher" daemon prio=10 tid=0x02443400 nid=0xf08 runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"Finalizer" daemon prio=8 tid=0x02412400 nid=0x13cc in Object.wait() [0x186bf000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x099d6410> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
    - locked <0x099d6410> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

   Locked ownable synchronizers:
    - None

"Reference Handler" daemon prio=10 tid=0x0240d800 nid=0xbe4 in Object.wait() [0x1862f000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x099d6498> (a java.lang.ref.Reference$Lock)
    at java.lang.Object.wait(Object.java:485)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
    - locked <0x099d6498> (a java.lang.ref.Reference$Lock)

   Locked ownable synchronizers:
    - None

"main" prio=6 tid=0x0011e000 nid=0x1028 in Object.wait() [0x003ce000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x09efc2a0> (a org.h2.engine.Database)
    at org.h2.table.RegularTable.doLock(RegularTable.java:520)
    at org.h2.table.RegularTable.lock(RegularTable.java:434)
    - locked <0x09efc2a0> (a org.h2.engine.Database)
    at org.h2.command.ddl.AlterTableAddConstraint.tryUpdate(AlterTableAddConstraint.java:93)
    at org.h2.command.ddl.AlterTableAddConstraint.update(AlterTableAddConstraint.java:68)
    at org.h2.command.CommandContainer.update(CommandContainer.java:73)
    at org.h2.command.Command.executeUpdate(Command.java:219)
    - locked <0x09efc2a0> (a org.h2.engine.Database)
    at org.h2.jdbc.JdbcStatement.executeUpdateInternal(JdbcStatement.java:125)
    - locked <0x0b69dd50> (a org.h2.engine.Session)
    at org.h2.jdbc.JdbcStatement.executeUpdate(JdbcStatement.java:110)
    at org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:421)
    at org.hibernate.tool.hbm2ddl.SchemaExport.create(SchemaExport.java:379)
    at org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:273)
    at org.hibernate.tool.hbm2ddl.SchemaExport.create(SchemaExport.java:219)
    at org.hibernate.impl.SessionFactoryImpl.<init>(SessionFactoryImpl.java:372)
    at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1845)
    at de.xyz.dps.server.core.database.HibernateUtil.createSessionFactory(HibernateUtil.java:55)
    at de.xyz.dps.server.core.database.HibernateUtil.getSessionFactory(HibernateUtil.java:40)
    at de.xyz.dps.server.core.database.TransactionContext.getContext(TransactionContext.java:52)
    at de.xyz.dps.server.core.serviceimpl.AbstractDatabaseService.getSession(AbstractDatabaseService.java:53)
    at de.xyz.dps.server.core.serviceimpl.AbstractDatabaseService.save(AbstractDatabaseService.java:36)
    at de.xyz.dps.server.core.serviceimpl.AbstractDatabaseService.save(AbstractDatabaseService.java:31)
    at de.xyz.dps.server.authentication.serviceimpl.DatabaseUserServiceTest.prepareAndSaveATechnicalSectionTO(DatabaseUserServiceTest.java:328)
    at de.xyz.dps.server.authentication.serviceimpl.DatabaseUserServiceTest.setup(DatabaseUserServiceTest.java:87)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
    at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:27)
    at de.xyz.dps.server.core.database.SessionFactoryRule$1.evaluate(SessionFactoryRule.java:90)
    at de.xyz.dps.common.util.ThreadRegistryRule$1.evaluate(ThreadRegistryRule.java:34)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
    at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:49)
    at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
    at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467)
    at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683)
    at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390)
    at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197)

   Locked ownable synchronizers:
    - None

"VM Thread" prio=10 tid=0x0240a400 nid=0x102c runnable 

"VM Periodic Task Thread" prio=10 tid=0x0245e400 nid=0xdf4 waiting on condition 

JNI global references: 967

Seems the test is waiting for some DB lock when creating the schema.

edit 3:

It seems to be a problem with multiple connections. When I replace jdbc:h2:mem:test (multiple connections in one process) with jdbc:h2:mem: (unnamed private; one connection), everything is fine (but ~10% slower than it was in hsql db).

edit 4:

Ok, i ran the test against a file db and could find the trace file on this way. The problem is the same here. trace file

Answer 1

The problem is solved. There were two tests out of 800 that didn't clean up their sessions and let them open. Seems HSQL DB is more tolerant towards this problem. All in all we have slowdown of about 5%.

Thanks to Thomas Mueller for his support.