Issue Details (XML | Word | Printable)

Key: TRUEZIP-268
Type: Bug Bug
Status: Closed Closed
Resolution: Fixed
Priority: Major Major
Assignee: Christian Schlichtherle
Reporter: Christian Schlichtherle
Votes: 0
Watchers: 0
Operations

If you were logged in you would be able to see more operations.
TrueZIP

Using FsSyncOption.CLEAR_CACHE induces extended dead locks in other threads

Created: 06/Jul/12 09:43 AM   Updated: 29/Aug/12 07:57 AM   Resolved: 17/Jul/12 08:20 PM
Component/s: TrueZIP Kernel
Affects Version/s: TrueZIP 7.5.5
Fix Version/s: TrueZIP 7.6

Time Tracking:
Not Specified

Issue Links:
Dependency
 
Related

Tags:
Participants: Christian Schlichtherle


 Description  « Hide

When running TrueZIP's integration test suite, an extended dead lock may happen as the following output from JVisualVM's ThreadInspector shows:

2012-07-06 10:39:25

"de.schlichtherle.truezip.io.Streams$ReaderThread" - Thread t@656
   java.lang.Thread.State: WAITING
	at sun.misc.Unsafe.park(Native Method)
	- waiting to lock <14f5969> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) owned by "main" t@1
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:867)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1197)
	at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:214)
	at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:290)
	at de.schlichtherle.truezip.io.LockInputStream.read(LockInputStream.java:61)
	at de.schlichtherle.truezip.io.DecoratingInputStream.read(DecoratingInputStream.java:54)
	at de.schlichtherle.truezip.io.DecoratingInputStream.read(DecoratingInputStream.java:54)
	at de.schlichtherle.truezip.io.Streams$1ReaderTask.run(Streams.java:174)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
	at java.util.concurrent.FutureTask.run(FutureTask.java:166)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
	at java.lang.Thread.run(Thread.java:722)

   Locked ownable synchronizers:
	- locked <32c746> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"main" - Thread t@1
   java.lang.Thread.State: WAITING
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for <51a79b> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
	at de.schlichtherle.truezip.io.Streams.cat(Streams.java:210)
	at de.schlichtherle.truezip.io.Streams.copy(Streams.java:71)
	at de.schlichtherle.truezip.socket.IOSocket.copy(IOSocket.java:118)
	at de.schlichtherle.truezip.socket.IOCache$InputBufferPool.allocate(IOCache.java:318)
	at de.schlichtherle.truezip.socket.IOCache$Input.getDelegate(IOCache.java:274)
	at de.schlichtherle.truezip.socket.DelegatingInputSocket.getBoundSocket(DelegatingInputSocket.java:43)
	at de.schlichtherle.truezip.socket.DelegatingInputSocket.newReadOnlyFile(DelegatingInputSocket.java:53)
	at de.schlichtherle.truezip.socket.DelegatingInputSocket.newReadOnlyFile(DelegatingInputSocket.java:53)
	at de.schlichtherle.truezip.fs.FsSyncController$Input.newReadOnlyFile(FsSyncController.java:400)
	at de.schlichtherle.truezip.fs.FsLockController$Input$1NewReadOnlyFile.call(FsLockController.java:481)
	at de.schlichtherle.truezip.fs.FsLockController$Input$1NewReadOnlyFile.call(FsLockController.java:478)
	at de.schlichtherle.truezip.fs.FsLockController.locked(FsLockController.java:352)
	at de.schlichtherle.truezip.fs.FsLockController.writeLocked(FsLockController.java:303)
	at de.schlichtherle.truezip.fs.FsLockController$Input.newReadOnlyFile(FsLockController.java:486)
	at de.schlichtherle.truezip.fs.FsFinalizeController$Input.newReadOnlyFile(FsFinalizeController.java:170)
	at de.schlichtherle.truezip.fs.FsFalsePositiveController$1Input$NewReadOnlyFile.call(FsFalsePositiveController.java:328)
	at de.schlichtherle.truezip.fs.FsFalsePositiveController$1Input$NewReadOnlyFile.call(FsFalsePositiveController.java:321)
	at de.schlichtherle.truezip.fs.FsFalsePositiveController$TryChild.call(FsFalsePositiveController.java:536)
	at de.schlichtherle.truezip.fs.FsFalsePositiveController.call(FsFalsePositiveController.java:104)
	at de.schlichtherle.truezip.fs.FsFalsePositiveController$1Input.newReadOnlyFile(FsFalsePositiveController.java:318)
	at de.schlichtherle.truezip.fs.archive.zip.ZipDriver.newInputShop(ZipDriver.java:468)
	at de.schlichtherle.truezip.fs.archive.FsTargetArchiveController.mount0(FsTargetArchiveController.java:219)
	at de.schlichtherle.truezip.fs.archive.FsTargetArchiveController.mount(FsTargetArchiveController.java:174)
	at de.schlichtherle.truezip.fs.archive.FsFileSystemArchiveController$ResetFileSystem.autoMount(FsFileSystemArchiveController.java:86)
	at de.schlichtherle.truezip.fs.archive.FsFileSystemArchiveController.autoMount(FsFileSystemArchiveController.java:38)
	at de.schlichtherle.truezip.fs.archive.FsArchiveController$1Output.mknod(FsArchiveController.java:274)
	at de.schlichtherle.truezip.fs.archive.FsArchiveController$1Output.getLocalTarget(FsArchiveController.java:221)
	at de.schlichtherle.truezip.fs.archive.FsArchiveController$1Output.getLocalTarget(FsArchiveController.java:218)
	at de.schlichtherle.truezip.fs.archive.FsContextController$Output.getLocalTarget(FsContextController.java:327)
	at de.schlichtherle.truezip.fs.archive.FsContextController$Output.getLocalTarget(FsContextController.java:311)
	at de.schlichtherle.truezip.socket.DelegatingOutputSocket.getLocalTarget(DelegatingOutputSocket.java:47)
	at de.schlichtherle.truezip.socket.DelegatingOutputSocket.getLocalTarget(DelegatingOutputSocket.java:21)
	at de.schlichtherle.truezip.socket.DelegatingOutputSocket.getLocalTarget(DelegatingOutputSocket.java:47)
	at de.schlichtherle.truezip.socket.DelegatingOutputSocket.getLocalTarget(DelegatingOutputSocket.java:21)
	at de.schlichtherle.truezip.fs.FsSyncController$Output.getLocalTarget(FsSyncController.java:455)
	at de.schlichtherle.truezip.fs.FsSyncController$Output.getLocalTarget(FsSyncController.java:442)
	at de.schlichtherle.truezip.fs.FsLockController$Output$1GetLocalTarget.call(FsLockController.java:539)
	at de.schlichtherle.truezip.fs.FsLockController$Output$1GetLocalTarget.call(FsLockController.java:536)
	at de.schlichtherle.truezip.fs.FsLockController.locked(FsLockController.java:352)
	at de.schlichtherle.truezip.fs.FsLockController.writeLocked(FsLockController.java:303)
	at de.schlichtherle.truezip.fs.FsLockController$Output.getLocalTarget(FsLockController.java:543)
	at de.schlichtherle.truezip.fs.FsLockController$Output.getLocalTarget(FsLockController.java:525)
	at de.schlichtherle.truezip.socket.DelegatingOutputSocket.getLocalTarget(DelegatingOutputSocket.java:47)
	at de.schlichtherle.truezip.socket.DelegatingOutputSocket.getLocalTarget(DelegatingOutputSocket.java:21)
	at de.schlichtherle.truezip.fs.FsFalsePositiveController$1Output$GetLocalTarget.call(FsFalsePositiveController.java:404)
	at de.schlichtherle.truezip.fs.FsFalsePositiveController$1Output$GetLocalTarget.call(FsFalsePositiveController.java:397)
	at de.schlichtherle.truezip.fs.FsFalsePositiveController$TryChild.call(FsFalsePositiveController.java:536)
	at de.schlichtherle.truezip.fs.FsFalsePositiveController.call(FsFalsePositiveController.java:104)
	at de.schlichtherle.truezip.fs.FsFalsePositiveController$1Output.getLocalTarget(FsFalsePositiveController.java:394)
	at de.schlichtherle.truezip.fs.FsFalsePositiveController$1Output.getLocalTarget(FsFalsePositiveController.java:378)
	at de.schlichtherle.truezip.socket.InputSocket.getPeerTarget(InputSocket.java:50)
	at de.schlichtherle.truezip.fs.archive.zip.ZipInputShop$1Input.newInputStream(ZipInputShop.java:130)
	at de.schlichtherle.truezip.socket.DisconnectingInputShop$Input.newInputStream(DisconnectingInputShop.java:162)
	at de.schlichtherle.truezip.socket.LockInputShop$1Input.newInputStream(LockInputShop.java:147)
	at de.schlichtherle.truezip.fs.archive.FsTargetArchiveController$1Input.newInputStream(FsTargetArchiveController.java:320)
	at de.schlichtherle.truezip.socket.DelegatingInputSocket.newInputStream(DelegatingInputSocket.java:63)
	at de.schlichtherle.truezip.fs.archive.FsContextController$Input.newInputStream(FsContextController.java:304)
	at de.schlichtherle.truezip.fs.FsResourceController$Input.newInputStream(FsResourceController.java:248)
	at de.schlichtherle.truezip.socket.DelegatingInputSocket.newInputStream(DelegatingInputSocket.java:63)
	at de.schlichtherle.truezip.fs.FsSyncController$Input.newInputStream(FsSyncController.java:412)
	at de.schlichtherle.truezip.fs.FsLockController$Input$1NewInputStream.call(FsLockController.java:494)
	at de.schlichtherle.truezip.fs.FsLockController$Input$1NewInputStream.call(FsLockController.java:491)
	at de.schlichtherle.truezip.fs.FsLockController.locked(FsLockController.java:364)
	at de.schlichtherle.truezip.fs.FsLockController.writeLocked(FsLockController.java:303)
	at de.schlichtherle.truezip.fs.FsLockController$Input.newInputStream(FsLockController.java:499)
	at de.schlichtherle.truezip.fs.FsFinalizeController$Input.newInputStream(FsFinalizeController.java:176)
	at de.schlichtherle.truezip.fs.FsFalsePositiveController$1Input$NewInputStream.call(FsFalsePositiveController.java:363)
	at de.schlichtherle.truezip.fs.FsFalsePositiveController$1Input$NewInputStream.call(FsFalsePositiveController.java:356)
	at de.schlichtherle.truezip.fs.FsFalsePositiveController$TryChild.call(FsFalsePositiveController.java:536)
	at de.schlichtherle.truezip.fs.FsFalsePositiveController.call(FsFalsePositiveController.java:104)
	at de.schlichtherle.truezip.fs.FsFalsePositiveController$1Input.newInputStream(FsFalsePositiveController.java:353)
	at de.schlichtherle.truezip.socket.IOSocket.copy(IOSocket.java:100)
	at de.schlichtherle.truezip.file.TBIO.cp0(TBIO.java:221)
	at de.schlichtherle.truezip.file.TBIO.cp(TBIO.java:208)
	at de.schlichtherle.truezip.file.TFile.cp_p(TFile.java:3083)
	at de.schlichtherle.truezip.file.TFileITSuite.assertCopyDelete0(TFileITSuite.java:941)
	at de.schlichtherle.truezip.file.TFileITSuite.assertCopyDelete0(TFileITSuite.java:925)
	at de.schlichtherle.truezip.file.TFileITSuite.assertCopyDelete(TFileITSuite.java:906)
	at de.schlichtherle.truezip.file.TFileITSuite.assertCopyDelete(TFileITSuite.java:889)
	at de.schlichtherle.truezip.file.TFileITSuite.testCopyDelete(TFileITSuite.java:873)
	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:45)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
	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:30)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:68)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:47)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
	at org.apache.maven.surefire.junitcore.ClassDemarcatingRunner.run(ClassDemarcatingRunner.java:58)
	at org.junit.runners.Suite.runChild(Suite.java:128)
	at org.junit.runners.Suite.runChild(Suite.java:24)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
	at org.apache.maven.surefire.junitcore.SynchronousRunner.schedule(SynchronousRunner.java:13)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:157)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:136)
	at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:62)
	at org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:139)
	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.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:189)
	at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:165)
	at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:85)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:103)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:74)

   Locked ownable synchronizers:
	- locked <14f5969> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

	- locked <818376> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)

	- locked <ddc385> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)

As you can see, the main thread is calling Streams.cat(InputStream, OutputStream). This method is awaiting a Condition (51a79b) which should get signaled by the ReaderThread. However, the ReaderThread needs to lock a ReentrantLock (14f5969) which is already acquired by the main thread. Voila, an extended dead lock!

I call this an "extended dead lock" because it involves awaiting a condition (in the main thread signaled by the ReaderThread) rather than locking a monitor. Unfortunately, such a condition is not detected by JConsole and YourKit. I'm not sure if this should get addressed by these tools, but that's not the topic here.



Christian Schlichtherle added a comment - 06/Jul/12 09:49 AM

There are some options to consider:

  1. Integrate the lock used by the LockInputShop into the lock management applied by the LockController. Unfortunately, in TrueZIP 7 this would require a serious refactoring. In TrueZIP 8 (a.k.a. TrueVFS), it would be much simpler.
  2. Make the LockInputShop temporarily release the lock when calling getPeerTarget(). Mind you that in TrueVFS sockets are stateless and therefore there is no getPeerTarget().
  3. Give the ReaderThread somehow reentrant access to all locks acquired by the calling thread of Streams.cat(InputStream, OutputStream). This would be a nice, general solution to avoid dead locks induced by a call to this method, but I don't think this is possible at all.
  4. Change the execution path somehow so that the call to Streams.cat(InputStream, OutputStream) is not required.

Christian Schlichtherle added a comment - 06/Jul/12 02:59 PM

Fixing this issue requires a bigger refactoring and should get addressed in TrueZIP 8, a.k.a. TrueVFS.

For now, the workaround is not to use CLEAR_CACHE when synchronizing archive files from a different thread than those who access these archive files.


Christian Schlichtherle added a comment - 07/Jul/12 05:11 PM

Changeset: 848924649349
Author: Christian Schlichtherle <christian AT schlichtherle DOT de>
Date: 2012-07-06 17:16
Message: Remove usage of CLEAR_CACHE in order to prevent possible dead locks or busy loops.
Issue #TRUEZIP-268 - Using FsSyncOption.CLEAR_CACHE induces extended dead locks in other threads