#220 Open project deadlock

[VaughanB]

I often have difficulty opening additional projects, with the editor hanging.

In the stack dump below, it seems that thread 30 is waiting for ArrayList 137, which is held by thread 5, which is waiting for ArrayList 141 (pendingPartitions from the IOConsolePartitioner), which is held by thread 8, which is waiting for SVDBSourceCollectionIndex 138, which is held by thread 30....so deadlock condition.

Thread [Worker-5] (Suspended)
owns: MessageConsoleStream (id=142)
owns: ArrayList<E> (id=137)
....waited by: Thread [Thread-30] (Suspended)
........owns: SVDBSourceCollectionIndex (id=138)
............waited by: Thread [Worker-8] (Suspended)
owns: SVDBWSFileSystemProvider (id=143)
owns: ArrayList<E> (id=144)
waiting for: ArrayList<E> (id=141)
Object.wait(long) line: not available [native method]
ArrayList<E>(Object).wait() line: 502
IOConsolePartitioner.streamAppended(IOConsoleOutputStream, String) line: 471
MessageConsoleStream(IOConsoleOutputStream).notifyParitioner(String) line: 245
MessageConsoleStream(IOConsoleOutputStream).encodedWrite(String) line: 240
MessageConsoleStream(IOConsoleOutputStream).write(String) line: 225
MessageConsoleStream.print(String) line: 56
MessageConsoleStream.println(String) line: 81
SVUiPlugin.message(ILogHandle, int, int, String) line: 266
LogFactory.message(ILogHandle, int, int, String) line: 134
LogHandle.println(int, int, String) line: 86
LogHandle.debug(int, String) line: 111
SVDBLibIndex(AbstractSVDBIndex).fileAdded(String) line: 632
SVDBWSFileSystemProvider.visit(IResourceDelta) line: 500
ResourceDelta.accept(IResourceDeltaVisitor, int) line: 69
ResourceDelta.accept(IResourceDeltaVisitor, int) line: 80
ResourceDelta.accept(IResourceDeltaVisitor, int) line: 80
ResourceDelta.accept(IResourceDeltaVisitor, int) line: 80
ResourceDelta.accept(IResourceDeltaVisitor, int) line: 80
ResourceDelta.accept(IResourceDeltaVisitor, int) line: 80
ResourceDelta.accept(IResourceDeltaVisitor, int) line: 80
ResourceDelta.accept(IResourceDeltaVisitor, int) line: 80
ResourceDelta.accept(IResourceDeltaVisitor, int) line: 80
ResourceDelta.accept(IResourceDeltaVisitor, int) line: 80
ResourceDelta.accept(IResourceDeltaVisitor, int) line: 80
ResourceDelta.accept(IResourceDeltaVisitor, int) line: 80
ResourceDelta.accept(IResourceDeltaVisitor) line: 49
SVDBWSFileSystemProvider.resourceChanged(IResourceChangeEvent) line: 527
NotificationManager$1.run() line: 291
SafeRunner.run(ISafeRunnable) line: 42
NotificationManager.notify(ResourceChangeListenerList$ListenerEntry[], IResourceChangeEvent, boolean) line: 285
NotificationManager.broadcastChanges(ElementTree, ResourceChangeEvent, boolean) line: 149
Workspace.broadcastPostChange() line: 395
Workspace.endOperation(ISchedulingRule, boolean, IProgressMonitor) line: 1530
OpenResourceAction$1(InternalWorkspaceJob).run(IProgressMonitor) line: 45
Worker.run() line: 54

Thread [Thread-30] (Suspended)
owns: SVDBSourceCollectionIndex (id=138)
....waited by: Thread [Worker-8] (Suspended)
waiting for: ArrayList<E> (id=137)
....owned by: Thread [Worker-5] (Suspended)
........waiting for: ArrayList<E> (id=141)
LogFactory.message(ILogHandle, int, int, String) line: 126
LogHandle.println(int, int, String) line: 86
LogHandle.debug(String) line: 94
SVDBSourceCollectionIndex(AbstractSVDBIndex).findIncludedFile(String) line: 1228
SVDBSourceCollectionIndex(AbstractSVDBIndex).findIncludedFileGlobal(String) line: 1483
SVDBSourceCollectionIndex(AbstractSVDBIndex).addPreProcFileIncludeFiles(SVDBFileTree, ISVDBScopeItem, List<SVDBMarker>, List<String>, Set<String>, Map<String,SVDBFileTree>) line: 1122
SVDBSourceCollectionIndex(AbstractSVDBIndex).buildPreProcFileMap(SVDBFileTree, SVDBFileTree, List<String>, Set<String>, Map<String,SVDBFileTree>) line: 1097
SVDBSourceCollectionIndex(AbstractSVDBIndex).addPreProcFileIncludeFiles(SVDBFileTree, ISVDBScopeItem, List<SVDBMarker>, List<String>, Set<String>, Map<String,SVDBFileTree>) line: 1144
SVDBSourceCollectionIndex(AbstractSVDBIndex).buildPreProcFileMap(SVDBFileTree, SVDBFileTree, List<String>, Set<String>, Map<String,SVDBFileTree>) line: 1097
SVDBSourceCollectionIndex(AbstractSVDBIndex).buildFileTreeJob(List<String>, List<String>, IProgressMonitor) line: 1059
SVDBSourceCollectionIndex(AbstractSVDBIndex).buildFileTree(IProgressMonitor) line: 984
SVDBSourceCollectionIndex(AbstractSVDBIndex).ensureIndexState(IProgressMonitor, int) line: 396
SVDBSourceCollectionIndex(AbstractSVDBIndex).findFile(IProgressMonitor, String) line: 732
SVDBSourceCollectionIndex(AbstractSVDBIndex).findFile(String) line: 1598
SVDBIndexCollection.findFile(String, boolean) line: 496
SVDBFileDecorator$1.run() line: 67
Thread.run() line: 679

Thread [Worker-8] (Suspended)
waiting for: SVDBSourceCollectionIndex (id=138)
....owned by: Thread [Thread-30] (Suspended)
........waiting for: ArrayList<E> (id=137)
............owned by: Thread [Worker-5] (Suspended)
................waiting for: ArrayList<E> (id=141)
SVDBSourceCollectionIndex(AbstractSVDBIndex).findPreProcFile(String) line: 1657
SVDBIndexCollection.findPreProcFile(String, boolean) line: 462
SVDBIndexUtil.findIndexFile(String, String, boolean) line: 83
UpdateProjectSettingsJob.run(IProgressMonitor) line: 49
Worker.run() line: 54

[VaughanB]

This may possibly only occur when the SVEd debug level is not set to off -- it certainly seems to make it more likely. Plus thread 5 above is a LogHandle.debug call, so likely workaround is to turn off debug output.

[VaughanB]

One more comment: this stack trace is for commit #6e8da373.

[Matthew Ballance]

I've made a change in the debug logging to avoid multiple threads outputting debug messages at the same time. Have a check with top-of-trunk to see whether or not the change imrproves thing...

[VaughanB]

That seems to prevent the deadlock. As a side note, upon closing a project (and particularly a project with a large number of other files ) and running a debugging session, there are numerous exceptions going off in the background in the debug console.

org.eclipse.core.internal.resources.ResourceException: Resource '...snip...' does not exist.
at org.eclipse.core.internal.resources.Resource.checkExists(Resource.java:341)
at org.eclipse.core.internal.resources.Resource.checkAccessible(Resource.java:215)
at org.eclipse.core.internal.resources.Resource.findMaxProblemSeverity(Resource.java:1052)
at net.sf.sveditor.ui.explorer.ProblemLabelDecorator.decorate(ProblemLabelDecorator.java:41)
at org.eclipse.ui.internal.decorators.LightweightDecoratorDefinition.decorate(LightweightDecoratorDefinition.java:269)
at org.eclipse.ui.internal.decorators.LightweightDecoratorManager$LightweightRunnable.run(LightweightDecoratorManager.java:81)
at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:42)
at org.eclipse.ui.internal.decorators.LightweightDecoratorManager.decorate(LightweightDecoratorManager.java:365)
at org.eclipse.ui.internal.decorators.LightweightDecoratorManager.getDecorations(LightweightDecoratorManager.java:347)
at org.eclipse.ui.internal.decorators.DecorationScheduler$1.ensureResultCached(DecorationScheduler.java:371)
at org.eclipse.ui.internal.decorators.DecorationScheduler$1.run(DecorationScheduler.java:331)
at org.eclipse.core.internal.jobs.Worker.run(Worker.java:54)

Adding a test for the project being open in ProblemLabelDecorator.decorate helps:

IProject prj = res.getProject();
if(!prj.isOpen())
return;

...although this might not be entirely correct, since it also stops the project icon getting updated to indicate the project is closed.

Upon opening the project (again, this might be exacerbated because I'm running a debug session) the editor will hang while all of the "[SourceCollectionIndex] fileAdded:" messages are output in the debug console, which can be quite a while for a project that has a whole lot of other non-source directories such as compiled simulation libraries etc. Not a problem if debug output is turned off though.