Akiban Persistit

Deadlock in Bug882219Test

Bug #1159313 reported by Peter Beaman
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Akiban Persistit
Incomplete
Low
Peter Beaman
Akiban Persistit 3.3.0

Bug Description

Persistit 3.2.7 r426

Observed during a build:

Full thread dump Java HotSpot(TM) 64-Bit Server VM (23.5-b02 mixed mode):

"Interrupter" prio=10 tid=0x00007f22d005c800 nid=0xfac waiting for monitor entry [0x00007f22d5c98000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at java.nio.channels.spi.AbstractInterruptibleChannel$1.interrupt(AbstractInterruptibleChannel.java:160)
 - waiting to lock <0x00000000f3f3e5a8> (a java.lang.Object)
 at java.lang.Thread.interrupt(Thread.java:935)
 - locked <0x00000000d81db5d8> (a java.lang.Object)
 at com.persistit.Bug882219Test$1.run(Bug882219Test.java:64)
 at java.util.TimerThread.mainLoop(Timer.java:555)
 at java.util.TimerThread.run(Timer.java:505)

"CLEANUP_MANAGER" prio=10 tid=0x00007f22d000a000 nid=0xfab in Object.wait() [0x00007f22d5652000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 at com.persistit.IOTaskRunnable.run(IOTaskRunnable.java:172)
 - locked <0x00000000f2b4d928> (a com.persistit.CleanupManager)
 at java.lang.Thread.run(Thread.java:722)

"CHECKPOINT_WRITER" prio=10 tid=0x00007f22d01c9000 nid=0xfaa in Object.wait() [0x00007f22d5894000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 at com.persistit.IOTaskRunnable.run(IOTaskRunnable.java:172)
 - locked <0x00000000f2b4d820> (a com.persistit.CheckpointManager)
 at java.lang.Thread.run(Thread.java:722)

"TXN_UPDATE" prio=10 tid=0x00007f22d01c8000 nid=0xfa9 in Object.wait() [0x00007f22d5e9a000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 at com.persistit.IOTaskRunnable.run(IOTaskRunnable.java:172)
 - locked <0x00000000f3f42340> (a com.persistit.TransactionIndex$ActiveTransactionCachePollTask)
 at java.lang.Thread.run(Thread.java:722)

"PAGE_WRITER:16384" prio=10 tid=0x00007f22d09de800 nid=0xfa8 in Object.wait() [0x00007f22d5a96000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 at com.persistit.IOTaskRunnable.run(IOTaskRunnable.java:172)
 - locked <0x00000000f2e1b3d0> (a com.persistit.BufferPool$PageWriter)
 at java.lang.Thread.run(Thread.java:722)

"JOURNAL_FLUSHER" prio=10 tid=0x00007f22d01d1000 nid=0xfa7 in Object.wait() [0x00007f22d5b97000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 at com.persistit.IOTaskRunnable.run(IOTaskRunnable.java:172)
 - locked <0x00000000f3f3fce8> (a com.persistit.JournalManager$JournalFlusher)
 at java.lang.Thread.run(Thread.java:722)

"JOURNAL_COPIER" prio=10 tid=0x00007f22d033e800 nid=0xfa6 in Object.wait() [0x00007f22d5d99000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 at com.persistit.IOTaskRunnable.run(IOTaskRunnable.java:172)
 - locked <0x00000000f3f3fda0> (a com.persistit.JournalManager$JournalCopier)
 at java.lang.Thread.run(Thread.java:722)

"LOG_FLUSHER" daemon prio=10 tid=0x00007f22d0349800 nid=0xfa5 waiting on condition [0x00007f22d5995000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
 at java.lang.Thread.sleep(Native Method)
 at com.persistit.util.Util.sleep(Util.java:557)
 at com.persistit.Persistit$LogFlusher.run(Persistit.java:186)

"Service Thread" daemon prio=10 tid=0x0000000000eb6000 nid=0xd5e runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" daemon prio=10 tid=0x0000000000eb3800 nid=0xd5d waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" daemon prio=10 tid=0x0000000000eb1000 nid=0xd5c waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"JDWP Event Helper Thread" daemon prio=10 tid=0x0000000000ea4800 nid=0xd5b runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"JDWP Transport Listener: dt_socket" daemon prio=10 tid=0x0000000000ea1000 nid=0xd5a runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x0000000000e93800 nid=0xd59 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x0000000000e48000 nid=0xd58 in Object.wait() [0x00007f22d70e2000]
   java.lang.Thread.State: WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 - waiting on <0x00000000d8017700> (a java.lang.ref.ReferenceQueue$Lock)
 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
 - locked <0x00000000d8017700> (a java.lang.ref.ReferenceQueue$Lock)
 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
 at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:177)

"Reference Handler" daemon prio=10 tid=0x0000000000e40800 nid=0xd57 in Object.wait() [0x00007f22d71e3000]
   java.lang.Thread.State: WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 - waiting on <0x00000000d80173d8> (a java.lang.ref.Reference$Lock)
 at java.lang.Object.wait(Object.java:503)
 at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
 - locked <0x00000000d80173d8> (a java.lang.ref.Reference$Lock)

"main" prio=10 tid=0x0000000000d2d000 nid=0xd50 waiting for monitor entry [0x00007f22df8d6000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at java.lang.Thread.interrupt(Thread.java:932)
 - waiting to lock <0x00000000d81db5d8> (a java.lang.Object)
 at sun.nio.ch.NativeThreadSet.signalAndWait(NativeThreadSet.java:108)
 - locked <0x00000000f3f3e5b8> (a sun.nio.ch.NativeThreadSet)
 at sun.nio.ch.FileChannelImpl.implCloseChannel(FileChannelImpl.java:114)
 at java.nio.channels.spi.AbstractInterruptibleChannel$1.interrupt(AbstractInterruptibleChannel.java:165)
 - locked <0x00000000f3f3e5a8> (a java.lang.Object)
 at java.nio.channels.spi.AbstractInterruptibleChannel.begin(AbstractInterruptibleChannel.java:173)
 at sun.nio.ch.FileChannelImpl.read(FileChannelImpl.java:669)
 at com.persistit.MediatedFileChannel.read(MediatedFileChannel.java:172)
 at com.persistit.JournalManager.readFully(JournalManager.java:729)
 at com.persistit.JournalManager.readPageBufferFromJournal(JournalManager.java:805)
 at com.persistit.JournalManager.readPageFromJournal(JournalManager.java:754)
 at com.persistit.VolumeStorageV2.readPage(VolumeStorageV2.java:448)
 at com.persistit.Buffer.load(Buffer.java:463)
 at com.persistit.BufferPool.get(BufferPool.java:860)
 at com.persistit.Exchange.searchLevel(Exchange.java:1289)
 at com.persistit.Exchange.searchTree(Exchange.java:1194)
 at com.persistit.Exchange.storeInternal(Exchange.java:1517)
 at com.persistit.Exchange.store(Exchange.java:1366)
 at com.persistit.Exchange.store(Exchange.java:2744)
 at com.persistit.Bug882219Test.testInterrupts(Bug882219Test.java:81)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke(Method.java:601)
 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.InvokeMethod.evaluate(InvokeMethod.java:20)
 at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
 at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
 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.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:62)
 at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140)
 at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127)
 at org.apache.maven.surefire.Surefire.run(Surefire.java:177)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke(Method.java:601)
 at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:338)
 at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:997)

"VM Thread" prio=10 tid=0x0000000000e39000 nid=0xd56 runnable

"GC task thread#0 (ParallelGC)" prio=10 tid=0x0000000000d3b000 nid=0xd54 runnable

"GC task thread#1 (ParallelGC)" prio=10 tid=0x0000000000d3c800 nid=0xd55 runnable

"VM Periodic Task Thread" prio=10 tid=0x0000000000ec1000 nid=0xd5f waiting on condition

JNI global references: 1800

Found one Java-level deadlock:
=============================
"Interrupter":
  waiting to lock monitor 0x00000000010b2600 (object 0x00000000f3f3e5a8, a java.lang.Object),
  which is held by "main"
"main":
  waiting to lock monitor 0x00000000012c5928 (object 0x00000000d81db5d8, a java.lang.Object),
  which is held by "Interrupter"

Java stack information for the threads listed above:
===================================================
"Interrupter":
 at java.nio.channels.spi.AbstractInterruptibleChannel$1.interrupt(AbstractInterruptibleChannel.java:160)
 - waiting to lock <0x00000000f3f3e5a8> (a java.lang.Object)
 at java.lang.Thread.interrupt(Thread.java:935)
 - locked <0x00000000d81db5d8> (a java.lang.Object)
 at com.persistit.Bug882219Test$1.run(Bug882219Test.java:64)
 at java.util.TimerThread.mainLoop(Timer.java:555)
 at java.util.TimerThread.run(Timer.java:505)
"main":
 at java.lang.Thread.interrupt(Thread.java:932)
 - waiting to lock <0x00000000d81db5d8> (a java.lang.Object)
 at sun.nio.ch.NativeThreadSet.signalAndWait(NativeThreadSet.java:108)
 - locked <0x00000000f3f3e5b8> (a sun.nio.ch.NativeThreadSet)
 at sun.nio.ch.FileChannelImpl.implCloseChannel(FileChannelImpl.java:114)
 at java.nio.channels.spi.AbstractInterruptibleChannel$1.interrupt(AbstractInterruptibleChannel.java:165)
 - locked <0x00000000f3f3e5a8> (a java.lang.Object)
 at java.nio.channels.spi.AbstractInterruptibleChannel.begin(AbstractInterruptibleChannel.java:173)
 at sun.nio.ch.FileChannelImpl.read(FileChannelImpl.java:669)
 at com.persistit.MediatedFileChannel.read(MediatedFileChannel.java:172)
 at com.persistit.JournalManager.readFully(JournalManager.java:729)
 at com.persistit.JournalManager.readPageBufferFromJournal(JournalManager.java:805)
 at com.persistit.JournalManager.readPageFromJournal(JournalManager.java:754)
 at com.persistit.VolumeStorageV2.readPage(VolumeStorageV2.java:448)
 at com.persistit.Buffer.load(Buffer.java:463)
 at com.persistit.BufferPool.get(BufferPool.java:860)
 at com.persistit.Exchange.searchLevel(Exchange.java:1289)
 at com.persistit.Exchange.searchTree(Exchange.java:1194)
 at com.persistit.Exchange.storeInternal(Exchange.java:1517)
 at com.persistit.Exchange.store(Exchange.java:1366)
 at com.persistit.Exchange.store(Exchange.java:2744)
 at com.persistit.Bug882219Test.testInterrupts(Bug882219Test.java:81)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke(Method.java:601)
 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.InvokeMethod.evaluate(InvokeMethod.java:20)
 at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
 at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
 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.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:62)
 at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140)
 at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127)
 at org.apache.maven.surefire.Surefire.run(Surefire.java:177)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke(Method.java:601)
 at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:338)
 at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:997)

Found 1 deadlock.

Heap
 PSYoungGen total 199424K, used 149098K [0x00000000f2ab0000, 0x00000000ffc20000, 0x0000000100000000)
  eden space 199360K, 74% used [0x00000000f2ab0000,0x00000000fbc4aa78,0x00000000fed60000)
  from space 64K, 0% used [0x00000000fed60000,0x00000000fed60000,0x00000000fed70000)
  to space 7552K, 0% used [0x00000000ff4c0000,0x00000000ff4c0000,0x00000000ffc20000)
 ParOldGen total 160192K, used 3199K [0x00000000d8000000, 0x00000000e1c70000, 0x00000000f2ab0000)
  object space 160192K, 1% used [0x00000000d8000000,0x00000000d831ff00,0x00000000e1c70000)
 PSPermGen total 21504K, used 11731K [0x00000000d2e00000, 0x00000000d4300000, 0x00000000d8000000)
  object space 21504K, 54% used [0x00000000d2e00000,0x00000000d3974ea0,0x00000000d4300000)

Nathan Williams (nwilliams)
Changed in akiban-persistit:
milestone: none → 3.2.8
Peter Beaman (pbeaman)
Changed in akiban-persistit:
status: New → Incomplete
importance: Undecided → Low
assignee: nobody → Peter Beaman (pbeaman)
Revision history for this message
Peter Beaman (pbeaman) wrote :

After reviewing code I am persuaded that this is a bug in the Java 7 libraries, not in Persistit. In particular, the "Interrupter" thread created by the test has no synchronization in the Persistit code base, and therefore nothing done by Persistit could cause the deadlock.

I believe the culprit is in the Interruptible instance created by AbstractInterruptibleChannel#begin(). Within a block synchronized on a private object closeLock it calls implCloseChannel, which then calls Thread#interrupt() on a different thread. Thread#interrupt() is synchronized on its own private object (blockerLock), and that monitor is held by the original thread that performed the interrupt.

I am marking this "Invalid" so that it remains visible on our bug history. At some point I will also write it up for the bug parade.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.