JE TimeoutException in core deadlock test

[gburd]

Hello, this is a spectacular combination of Clojure and BDB JE. As the product manager for Oracle Berkeley DB products and a big fan of Clojure I couldn't be happier to see the two combined.

The test.cupboard.core/deadlock test fails due to a lock timeout. I'm trying to sort that out in my fork, but I thought I'd report it to you here in case you have ideas. In my fork I've updated to the later version of BDB JE (.103) but that didn't effect this issue.

Here is the stack:

gburd@monk:/eng/cupboard$ java -version
java version "1.6.0_18"
OpenJDK Runtime Environment (IcedTea6 1.8) (6b18-1.8-0ubuntu1)
OpenJDK Server VM (build 14.0-b16, mixed mode)
gburd@monk:/eng/cupboard$ uname -a
Linux monk 2.6.32-23-generic #37-Ubuntu SMP Fri Jun 11 07:54:58 UTC 2010 i686 GNU/Linux
gburd@monk:~/eng/cupboard$ lein test

Testing test.cupboard.bdb.je

Ran 12 tests containing 108 assertions.
0 failures, 0 errors.

Testing test.cupboard.bdb.je-marshal

Ran 4 tests containing 32 assertions.
0 failures, 0 errors.

Testing test.cupboard.core
Exception in thread "Thread-1" java.lang.RuntimeException: java.lang.RuntimeException: com.sleepycat.je.LockTimeoutException: (JE 4.0.103) Lock expired. Locker 33296132 17_Thread-1_Txn: waited for lock on database=_default LockAddr:9381256 node=47 type=WRITE grant=WAIT_NEW timeoutMillis=500 startTime=1277051991364 endTime=1277051991864
Owners: []
Waiters: []
Transaction 7055953 18_Thread-2_Txn waits for LockAddr:19399826 Owners: Waiters:[]
Transaction 33296132 17_Thread-1_Txn owns LockAddr:19399826
Transaction 33296132 17_Thread-1_Txn waits for LockAddr:9381256

at clojure.lang.AFn.run(AFn.java:41)
at java.lang.Thread.run(Thread.java:636)

Caused by: java.lang.RuntimeException: com.sleepycat.je.LockTimeoutException: (JE 4.0.103) Lock expired. Locker 33296132 17_Thread-1_Txn: waited for lock on database=_default LockAddr:9381256 node=47 type=WRITE grant=WAIT_NEW timeoutMillis=500 startTime=1277051991364 endTime=1277051991864
Owners: []
Waiters: []
Transaction 7055953 18_Thread-2_Txn waits for LockAddr:19399826 Owners: Waiters:[]
Transaction 33296132 17_Thread-1_Txn owns LockAddr:19399826
Transaction 33296132 17_Thread-1_Txn waits for LockAddr:9381256

at test.cupboard.core$fn__4343$fn__4345$fn__4347$attempt_txn__3760__auto____4349.invoke(core.clj:287)
at test.cupboard.core$fn__4343$fn__4345$fn__4347.invoke(core.clj:287)
at clojure.lang.AFn.run(AFn.java:37)
... 1 more

Caused by: com.sleepycat.je.LockTimeoutException: (JE 4.0.103) Lock expired. Locker 33296132 17_Thread-1_Txn: waited for lock on database=_default LockAddr:9381256 node=47 type=WRITE grant=WAIT_NEW timeoutMillis=500 startTime=1277051991364 endTime=1277051991864
Owners: []
Waiters: []
Transaction 7055953 18_Thread-2_Txn waits for LockAddr:19399826 Owners: Waiters:[]
Transaction 33296132 17_Thread-1_Txn owns LockAddr:19399826
Transaction 33296132 17_Thread-1_Txn waits for LockAddr:9381256

at com.sleepycat.je.txn.LockManager.newLockTimeoutException(LockManager.java:608)
at com.sleepycat.je.txn.LockManager.makeTimeoutMsgInternal(LockManager.java:567)
at com.sleepycat.je.txn.SyncedLockManager.makeTimeoutMsg(SyncedLockManager.java:75)
at com.sleepycat.je.txn.LockManager.lockInternal(LockManager.java:385)
at com.sleepycat.je.txn.LockManager.lock(LockManager.java:272)
at com.sleepycat.je.txn.Txn.lockInternal(Txn.java:473)
at com.sleepycat.je.txn.Locker.lock(Locker.java:453)
at com.sleepycat.je.dbi.CursorImpl.lockLNDeletedAllowed(CursorImpl.java:2695)
at com.sleepycat.je.tree.Tree.insert(Tree.java:2564)
at com.sleepycat.je.dbi.CursorImpl.put(CursorImpl.java:1211)
at com.sleepycat.je.Cursor.putAllowPhantoms(Cursor.java:1799)
at com.sleepycat.je.Cursor.putNoNotify(Cursor.java:1756)
at com.sleepycat.je.Cursor.putNotify(Cursor.java:1689)
at com.sleepycat.je.Cursor.putInternal(Cursor.java:1626)
at com.sleepycat.je.Database.putInternal(Database.java:1186)
at com.sleepycat.je.Database.put(Database.java:1058)
at cupboard.bdb.je$db_put__3210.doInvoke(je.clj:510)
at clojure.lang.RestFn.invoke(RestFn.java:483)
at cupboard.core$save__3875.doInvoke(core.clj:716)
at clojure.lang.RestFn.invoke(RestFn.java:428)
at cupboard.core$passoc_BANG___3909.doInvoke(core.clj:784)
at clojure.lang.RestFn.invoke(RestFn.java:479)
at test.cupboard.core$fn__4343$fn__4345$fn__4347$attempt_txn__3760__auto____4349.invoke(core.clj:290)
... 3 more

[gcv]

Yes, I have seen this problem. It is not specific to IcedTea or Ubuntu, as it occurs on the JDK Apple ships with Mac OS X 10.6.

I suspect that the tests are fundamentally wrong. They rely on a specific ordering of events as two different threads run, a flawed assumption at best. I tried to mitigate the problem by adding fairly long delays between the interleaved events, but it does not seem to work as I expect.

At the moment, I can't think of a good way to test that deadlock detection works properly. Starting up two threads and executing transactions on both of them in a way that guarantees a deadlock seemed workable.