Unexpected RollbackException during MultiThreadedTest

[Jack Orenstein]

I ran MultiThreadedTest with 2 threads, each creating 5 COI groups. Even though the threads are writing rows with different PKs, a RollbackException is reported. The rollback does not appear to be due to application actions directly, but from a Persistit class named ClassIndex. The rollback does not occur with one application thread.

Marking this as Critical because it appears to be easy to provoke: Multiple threads doing writes. This occurred with autocommit set to either false or true.

Here is the stack:

Thread-5@3447, prio=5, in group 'main', status: 'RUNNING'
   at com.persistit.Exchange.storeInternal(Exchange.java:1636)
   at com.persistit.Exchange.store(Exchange.java:1299)
   at com.persistit.Exchange.store(Exchange.java:2544)
   at com.persistit.ClassIndex.lookupByClass(ClassIndex.java:254)
   at com.persistit.Value.put(Value.java:3419)
   at com.persistit.Value.put(Value.java:3224)
   at com.akiban.server.store.PersistitStore.packRowData(PersistitStore.java:1243)
   at com.akiban.server.store.PersistitStore.writeRow(PersistitStore.java:476)
   at com.akiban.server.store.PersistitStore.writeRow(PersistitStore.java:438)
   at com.akiban.server.store.DelegatingStore.writeRow(DelegatingStore.java:87)
   at com.akiban.qp.persistitadapter.OperatorStore.writeRow(OperatorStore.java:176)
   at com.akiban.qp.persistitadapter.PersistitAdapter.writeRow(PersistitAdapter.java:148)
   at com.akiban.qp.operator.Insert_Default$Execution.run(Insert_Default.java:146)
   at com.akiban.qp.operator.Insert_Default.run(Insert_Default.java:97)
   at com.akiban.sql.pg.PostgresModifyOperatorStatement.execute(PostgresModifyOperatorStatement.java:80)
   at com.akiban.sql.pg.PostgresServerConnection.executeStatement(PostgresServerConnection.java:734)
   at com.akiban.sql.pg.PostgresServerConnection.processExecute(PostgresServerConnection.java:592)
   at com.akiban.sql.pg.PostgresServerConnection.topLevel(PostgresServerConnection.java:211)
   at com.akiban.sql.pg.PostgresServerConnection.run(PostgresServerConnection.java:140)
   at java.lang.Thread.run(Thread.java:662)

This is completely reproducible. I suspect it's been happening for a while, but has become apparent due to therecent improved handling of rollbacks.

With N threads, the rollback is reported on N-1 of them, and it seems to always occur on the second group creation of each thread. (I've included complete output below from a run with 5 threads, each inserting 5 groups. The "thread X, creating customer Y" output comes from extra printlns that are not checked in.)

The test is not in trunk, but can be found in lp:~jack-akiban/akiban-build-scripts/20120713_multi_threaded_test. The output below was obtained with this command:

java -classpath target/MultiThreadedTest-jar-with-dependencies.jar com.akiban.test.multithread.MultiThreadedTest akiban thread.count=5 thread.initialGroups=5 thread.actions=0

thread 1, creating customer 1000000000
thread 2, creating customer 2000000000
thread 3, creating customer 3000000000
thread 4, creating customer 4000000000
thread 5, creating customer 5000000000
thread 2, creating customer 2000000001
thread 5: ERROR: QUERY_ROLLBACK: Rollback
org.postgresql.util.PSQLException: ERROR: QUERY_ROLLBACK: Rollback
 at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2102)
 at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1835)
 at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
 at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500)
 at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:388)
 at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:334)
 at com.akiban.test.multithread.CreateGroup.execute(CreateGroup.java:47)
 at com.akiban.test.multithread.TestThread.execute(TestThread.java:107)
 at com.akiban.test.multithread.TestThread.run(TestThread.java:45)
thread 5, creating customer 5000000001
thread 3: ERROR: QUERY_ROLLBACK: Rollback
org.postgresql.util.PSQLException: ERROR: QUERY_ROLLBACK: Rollback
 at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2102)
 at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1835)
 at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
 at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500)
 at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:388)
 at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:334)
 at com.akiban.test.multithread.CreateGroup.execute(CreateGroup.java:47)
 at com.akiban.test.multithread.TestThread.execute(TestThread.java:107)
 at com.akiban.test.multithread.TestThread.run(TestThread.java:45)
thread 3, creating customer 3000000001
thread 1: ERROR: QUERY_ROLLBACK: Rollback
org.postgresql.util.PSQLException: ERROR: QUERY_ROLLBACK: Rollback
 at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2102)
 at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1835)
 at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
 at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500)
 at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:388)
 at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:334)
 at com.akiban.test.multithread.CreateGroup.execute(CreateGroup.java:47)
 at com.akiban.test.multithread.TestThread.execute(TestThread.java:107)
 at com.akiban.test.multithread.TestThread.run(TestThread.java:45)
thread 1, creating customer 1000000001
thread 4: ERROR: QUERY_ROLLBACK: Rollback
org.postgresql.util.PSQLException: ERROR: QUERY_ROLLBACK: Rollback
 at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2102)
 at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1835)
 at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
 at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500)
 at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:388)
 at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:334)
 at com.akiban.test.multithread.CreateGroup.execute(CreateGroup.java:47)
 at com.akiban.test.multithread.TestThread.execute(TestThread.java:107)
 at com.akiban.test.multithread.TestThread.run(TestThread.java:45)
thread 4, creating customer 4000000001
thread 2, creating customer 2000000002
thread 3, creating customer 3000000002
thread 1, creating customer 1000000002
thread 4, creating customer 4000000002
thread 5, creating customer 5000000002
thread 2, creating customer 2000000003
thread 3, creating customer 3000000003
thread 4, creating customer 4000000003
thread 1, creating customer 1000000003
thread 5, creating customer 5000000003
thread 2, creating customer 2000000004
thread 1, creating customer 1000000004
thread 3, creating customer 3000000004
thread 5, creating customer 5000000004
thread 4, creating customer 4000000004
db.autocommit: false
db.driver: org.postgresql.Driver
db.password: password
db.url: jdbc:postgresql://localhost:15432/test
db.user: user
profile.action.CreateGroup: 0.6
profile.action.UpdateLeaves: 0.2
profile.action.ValidateGroup: 0.2
profile.itemsPerOrder: 4
profile.ordersPerCustomer: 5
thread.actions: 0
thread.count: 5
thread.initialGroups: 5
Average time per thread (sec): 0.587400
Average rollbacks per thread: 0.800000

[Nathan Williams (nwilliams)]

I'm assuming they all start their writes simultaneously? And that they can continue successfully after this rollback? If so, a work around should be to commit one write first and then I don't think there shouldn't be any ww-conflicts.

This needs fixed, but I'm not optimistic about getting one done today.

[Jack Orenstein (jack-akiban)]

Yes, they start at the same time and continue past it.

Staggering the thread starts does avoid the problem.

[Thomas Jones-Low (tjoneslo)]

I have also reproduced this exact problem with a completely different setup. The AAS proposed merge for the spawned Include, plus a multi-thread identity insert test (both are merge proposals for build scripts).