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)
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 AbstractInterru ptibleChannel# 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.