Deadlock in Bug882219Test

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

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)

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  Edit
Everyone can see this information.

Other bug subscribers