Tracing option for locks on the index, bug 271909.

3 files changed, 174 insertions, 14 deletions

diff --git a/core/org.eclipse.cdt.core/.options b/core/org.eclipse.cdt.core/.options
index eb67f9a90e3..2f198b497a9 100644
--- a/core/org.eclipse.cdt.core/.options
+++ b/core/org.eclipse.cdt.core/.options
@@ -24,6 +24,9 @@ org.eclipse.cdt.core/debug/deltaprocessor=false
 # Reports file type resolver activity
 org.eclipse.cdt.core/debug/typeresolver=false
 
+# Reports issues with locking the index
+org.eclipse.cdt.core/debug/index/locks=false
+
 # Reports sequence of files indexed
 org.eclipse.cdt.core/debug/indexer/activity=false
 
diff --git a/core/org.eclipse.cdt.core/parser/org/eclipse/cdt/internal/core/pdom/PDOM.java b/core/org.eclipse.cdt.core/parser/org/eclipse/cdt/internal/core/pdom/PDOM.java
index 4bb170558f2..8d4babc1bc7 100644
--- a/core/org.eclipse.cdt.core/parser/org/eclipse/cdt/internal/core/pdom/PDOM.java
+++ b/core/org.eclipse.cdt.core/parser/org/eclipse/cdt/internal/core/pdom/PDOM.java
@@ -87,6 +87,7 @@ import org.eclipse.core.runtime.CoreException;
 import org.eclipse.core.runtime.IProgressMonitor;
 import org.eclipse.core.runtime.NullProgressMonitor;
 import org.eclipse.core.runtime.OperationCanceledException;
+import org.eclipse.core.runtime.Platform;
 import org.eclipse.core.runtime.PlatformObject;
 import org.eclipse.core.runtime.Status;
 
@@ -95,6 +96,13 @@ import org.eclipse.core.runtime.Status;
  */
 public class PDOM extends PlatformObject implements IPDOM {
 	/**
+	 * mstodo
+	 */
+	private static final int BLOCKED_WRITELOCK_OUTPUT_INTERVAL = 30000;
+
+	static boolean sDEBUG_LOCKS= "true".equals(Platform.getDebugOption(CCorePlugin.PLUGIN_ID + "/debug/index/locks"));  //$NON-NLS-1$//$NON-NLS-2$
+
+	/**
 	 * Identifier for PDOM format
 	 * @see IIndexFragment#PROPERTY_FRAGMENT_FORMAT_ID
 	 */
@@ -232,6 +240,7 @@ public class PDOM extends PlatformObject implements IPDOM {
 	private HashMap<Object, Object> fResultCache= new HashMap<Object, Object>();
 	private List<IListener> listeners;
 	protected ChangeEvent fEvent= new ChangeEvent();
+	private Map<Thread, int[]> fLockDebugging;
 
 	public PDOM(File dbPath, IIndexLocationConverter locationConverter, Map<String, IPDOMLinkageFactory> linkageFactoryMappings) throws CoreException {
 		this(dbPath, locationConverter, ChunkCache.getSharedInstance(), linkageFactoryMappings);
@@ -241,6 +250,10 @@ public class PDOM extends PlatformObject implements IPDOM {
 		fPDOMLinkageFactoryCache = linkageFactoryMappings;
 		loadDatabase(dbPath, cache);
 		this.locationConverter = locationConverter;
+		if (sDEBUG_LOCKS) {
+			fLockDebugging= new HashMap<Thread, int[]>();
+			System.out.println("Debugging PDOM Locks"); //$NON-NLS-1$
+		}
 	}
 	
 	/**
@@ -675,13 +688,22 @@ public class PDOM extends PlatformObject implements IPDOM {
 			}
 			++lockCount;
 			db.setLocked(true);
+			
+			if (sDEBUG_LOCKS) {
+				incReadLock(fLockDebugging);
+			}
 		}
 	}
 
+
 	public void releaseReadLock() {
 		boolean clearCache= false;
 		synchronized (mutex) {
 			assert lockCount > 0: "No lock to release"; //$NON-NLS-1$
+			if (sDEBUG_LOCKS) {
+				decReadLock(fLockDebugging);
+			}
+			
 			lastReadAccess= System.currentTimeMillis();
 			if (lockCount > 0)
 				--lockCount;
@@ -712,6 +734,10 @@ public class PDOM extends PlatformObject implements IPDOM {
 	public void acquireWriteLock(int giveupReadLocks) throws InterruptedException {
 		assert !isPermanentlyReadOnly();
 		synchronized (mutex) {
+			if (sDEBUG_LOCKS) {
+				incWriteLock(giveupReadLocks);
+			}
+
 			if (giveupReadLocks > 0) {
 				// give up on read locks
 				assert lockCount >= giveupReadLocks: "Not enough locks to release"; //$NON-NLS-1$
@@ -724,8 +750,13 @@ public class PDOM extends PlatformObject implements IPDOM {
 			}
 
 			// Let the readers go first
-			while (lockCount > giveupReadLocks || waitingReaders > 0)
-				mutex.wait();
+			long start= sDEBUG_LOCKS ? System.currentTimeMillis() : 0;
+			while (lockCount > giveupReadLocks || waitingReaders > 0) {
+				mutex.wait(BLOCKED_WRITELOCK_OUTPUT_INTERVAL);
+				if (sDEBUG_LOCKS) {
+					start = reportBlockedWriteLock(start, giveupReadLocks);
+				}
+			}
 			lockCount= -1;
 			db.setExclusiveLock();
 		}
@@ -747,6 +778,10 @@ public class PDOM extends PlatformObject implements IPDOM {
 		final ChangeEvent event= fEvent;
 		fEvent= new ChangeEvent();
 		synchronized (mutex) {
+			if (sDEBUG_LOCKS) {
+				decWriteLock(establishReadLocks);
+			}
+
 			if (lockCount < 0)
 				lockCount= establishReadLocks;
 			mutex.notifyAll();
@@ -755,7 +790,6 @@ public class PDOM extends PlatformObject implements IPDOM {
 		fireChange(event);
 	}
 
-
 	public long getLastWriteAccess() {
 		return lastWriteAccess;
 	}
@@ -1188,4 +1222,110 @@ public class PDOM extends PlatformObject implements IPDOM {
 	public IIndexFragmentFileSet createFileSet() {
 		return new PDOMFileSet();
 	}
+	
+
+	// For debugging lock issues
+	private static int[] getLockCounter(Map<Thread, int[]> lockDebugging) {
+		assert sDEBUG_LOCKS;
+		
+		Thread key = Thread.currentThread();
+		int[] result= lockDebugging.get(key);
+		if (result == null) {
+			result= new int[]{0,0};
+			lockDebugging.put(key, result);
+		}
+		return result;
+	}
+
+	// For debugging lock issues
+	static void incReadLock(Map<Thread, int[]> lockDebugging) {
+		int[] lockCounter = getLockCounter(lockDebugging);
+		lockCounter[0]++;
+	}
+	
+	// For debugging lock issues
+	@SuppressWarnings("nls")
+	static void decReadLock(Map<Thread, int[]> lockDebugging) throws AssertionError {
+		int[] counter= getLockCounter(lockDebugging);
+		if (counter[0] <= 0) {
+			outputReadLocks(lockDebugging);
+			throw new AssertionError("Superfluous releaseReadLock");
+		}
+		if (counter[1] != 0) {
+			outputReadLocks(lockDebugging);
+			throw new AssertionError("Releasing readlock while holding write lock");
+		}
+		if (--counter[0] == 0) {
+			lockDebugging.remove(Thread.currentThread());
+		}
+	}
+
+	// For debugging lock issues
+	@SuppressWarnings("nls")
+	private void incWriteLock(int giveupReadLocks) throws AssertionError {
+		int[] counter= getLockCounter(fLockDebugging);
+		if (counter[0] != giveupReadLocks) {
+			outputReadLocks(fLockDebugging);
+			throw new AssertionError("write lock with " + giveupReadLocks + " readlocks, expected " + counter[0]);
+		}
+		if (counter[1] != 0)
+			throw new AssertionError("Duplicate write lock"); 
+		counter[1]++;
+	}
+
+	// For debugging lock issues
+	private void decWriteLock(int establishReadLocks) throws AssertionError {
+		int[] counter= getLockCounter(fLockDebugging);
+		if (counter[0] != establishReadLocks)
+			throw new AssertionError("release write lock with " + establishReadLocks + " readlocks, expected " + counter[0]); //$NON-NLS-1$ //$NON-NLS-2$
+		if (counter[1] != 1)
+			throw new AssertionError("Wrong release write lock"); //$NON-NLS-1$
+		counter[1]= 0;
+		if (counter[0] == 0) {
+			fLockDebugging.remove(Thread.currentThread());
+		}
+	}
+
+	// For debugging lock issues
+	@SuppressWarnings("nls")
+	private long reportBlockedWriteLock(long start, int giveupReadLocks) {
+		long now= System.currentTimeMillis();
+		if (now >= start+BLOCKED_WRITELOCK_OUTPUT_INTERVAL) {
+			System.out.println();
+			System.out.println("Blocked writeLock");
+			System.out.println("  lockcount= " + lockCount + ", giveupReadLocks=" + giveupReadLocks + ", waitingReaders=" + waitingReaders);
+			outputReadLocks(fLockDebugging);
+			start= now;
+		}
+		return start;
+	}
+
+	// For debugging lock issues
+	@SuppressWarnings("nls")
+	private static void outputReadLocks(Map<Thread, int[]> lockDebugging) {
+		for (Thread th: lockDebugging.keySet()) {
+			int[] counts = lockDebugging.get(th);
+			System.out.println(th.getName() + ":" + counts[0] + "," + counts[1]); 
+			for (StackTraceElement ste : th.getStackTrace()) {
+				System.out.println("  " + ste); 
+			}
+		}
+	}
+	
+	// For debugging lock issues
+	public void adjustThreadForReadLock(Map<Thread, int[]> lockDebugging) {
+		for (Thread th : lockDebugging.keySet()) {
+			int[] val= lockDebugging.get(th);
+			if (val[0] > 0) {
+				int[] myval= fLockDebugging.get(th);
+				if (myval == null) {
+					myval= new int[] {0,0};
+					fLockDebugging.put(th, myval);
+				}
+				myval[0]++;
+				decReadLock(fLockDebugging);
+				break;
+			}
+		}
+	}
 }
\ No newline at end of file
diff --git a/core/org.eclipse.cdt.core/parser/org/eclipse/cdt/internal/core/pdom/PDOMProxy.java b/core/org.eclipse.cdt.core/parser/org/eclipse/cdt/internal/core/pdom/PDOMProxy.java
index d80b82d95a8..4008a90a67f 100644
--- a/core/org.eclipse.cdt.core/parser/org/eclipse/cdt/internal/core/pdom/PDOMProxy.java
+++ b/core/org.eclipse.cdt.core/parser/org/eclipse/cdt/internal/core/pdom/PDOMProxy.java
@@ -1,5 +1,5 @@
 /*******************************************************************************
- * Copyright (c) 2007, 2008 Wind River Systems, Inc. and others.
+ * Copyright (c) 2007, 2009 Wind River Systems, Inc. and others.
  * All rights reserved. This program and the accompanying materials
  * are made available under the terms of the Eclipse Public License v1.0
  * which accompanies this distribution, and is available at
@@ -10,8 +10,10 @@
  *******************************************************************************/ 
 package org.eclipse.cdt.internal.core.pdom;
 
+import java.util.HashMap;
 import java.util.HashSet;
 import java.util.Iterator;
+import java.util.Map;
 import java.util.Set;
 import java.util.regex.Pattern;
 
@@ -41,12 +43,21 @@ public class PDOMProxy implements IPDOM {
 	private PDOM fDelegate;
 	private int fReadLockCount;
 	private Set<IListener> fListeners= new HashSet<IListener>();
+	private Map<Thread, int[]> fLockDebugging;
 
+	public PDOMProxy() {
+		if (PDOM.sDEBUG_LOCKS) {
+			fLockDebugging= new HashMap<Thread, int[]>();
+		}
+	}
 	public synchronized void acquireReadLock() throws InterruptedException {
 		if (fDelegate != null)
 			fDelegate.acquireReadLock();
 		else {
 			fReadLockCount++;
+			if (PDOM.sDEBUG_LOCKS) {
+				PDOM.incReadLock(fLockDebugging);
+			}
 		}
 	}
 
@@ -166,10 +177,13 @@ public class PDOMProxy implements IPDOM {
 	}
 
 	public synchronized void releaseReadLock() {
-		if (fDelegate != null)
-			fDelegate.releaseReadLock();
-		else {
+		// read-locks not forwarded to delegate need to be released here
+		if (fReadLockCount > 0) {
 			fReadLockCount--;
+			if (PDOM.sDEBUG_LOCKS)
+				PDOM.decReadLock(fLockDebugging);
+		} else if (fDelegate != null) {
+			fDelegate.releaseReadLock();
 		}
 	}
 
@@ -212,17 +226,20 @@ public class PDOMProxy implements IPDOM {
 	public synchronized void setDelegate(WritablePDOM pdom) {
 		fDelegate= pdom;
 		try {
-			while (fReadLockCount-- > 0) {
+			while (fReadLockCount > 0) {
 				pdom.acquireReadLock();
+				fReadLockCount--;
+				if (PDOM.sDEBUG_LOCKS) {
+					pdom.adjustThreadForReadLock(fLockDebugging);
+				}
 			} 
-			for (Iterator<IListener> iterator = fListeners.iterator(); iterator.hasNext();) {
-				IListener listener = iterator.next();
-				pdom.addListener(listener);
-			}
-		}
-		catch (InterruptedException e) {
+		} catch (InterruptedException e) {
 			Thread.currentThread().interrupt();
 		}
+		for (Iterator<IListener> iterator = fListeners.iterator(); iterator.hasNext();) {
+			IListener listener = iterator.next();
+			pdom.addListener(listener);
+		}
 		ChangeEvent event= new ChangeEvent();
 		event.fReloaded= true;
 		for (Iterator<IListener> iterator = fListeners.iterator(); iterator.hasNext();) {