Bug 482062 - Add diagnostic logging to SubMonitorI20160425-1300I20160425-0800I20160424-2245I20160424-2000

Change-Id: I8514964dc80a48a990e4d12bb4b0ff8b6dcefaed
Signed-off-by: Stefan Xenos <sxenos@gmail.com>

4 files changed, 116 insertions, 6 deletions

diff --git a/bundles/org.eclipse.equinox.common/.options b/bundles/org.eclipse.equinox.common/.options
index 0f8426666..71347b055 100644
--- a/bundles/org.eclipse.equinox.common/.options
+++ b/bundles/org.eclipse.equinox.common/.options
@@ -2,3 +2,6 @@
 
 # Turn on general debugging for the org.eclipse.equinox.common plugin.
 org.eclipse.equinox.common/debug=false
+
+# Enable diagnostic logging for progress monitoring
+org.eclipse.equinox.common/progress_monitors=false
diff --git a/bundles/org.eclipse.equinox.common/src/org/eclipse/core/internal/runtime/Activator.java b/bundles/org.eclipse.equinox.common/src/org/eclipse/core/internal/runtime/Activator.java
index 355ba8adf..fb5cbde09 100644
--- a/bundles/org.eclipse.equinox.common/src/org/eclipse/core/internal/runtime/Activator.java
+++ b/bundles/org.eclipse.equinox.common/src/org/eclipse/core/internal/runtime/Activator.java
@@ -21,6 +21,7 @@ import org.eclipse.equinox.log.ExtendedLogService;
 import org.eclipse.osgi.framework.log.FrameworkLog;
 import org.eclipse.osgi.service.datalocation.Location;
 import org.eclipse.osgi.service.debug.DebugOptions;
+import org.eclipse.osgi.service.debug.DebugOptionsListener;
 import org.eclipse.osgi.service.localization.BundleLocalization;
 import org.eclipse.osgi.service.urlconversion.URLConverter;
 import org.eclipse.osgi.util.NLS;
@@ -36,6 +37,7 @@ import org.osgi.util.tracker.ServiceTracker;
  * This class can only be used if OSGi plugin is available.
  */
 public class Activator implements BundleActivator {
+	public static final String PLUGIN_ID = "org.eclipse.equinox.common"; //$NON-NLS-1$ 
 
 	/**
 	 * Table to keep track of all the URL converter services.
@@ -52,6 +54,7 @@ public class Activator implements BundleActivator {
 	private ServiceTracker<Object, DebugOptions> debugTracker = null;
 	private ServiceTracker<Object, FrameworkLog> logTracker = null;
 	private ServiceTracker<Object, BundleLocalization> localizationTracker = null;
+	private ServiceRegistration<DebugOptionsListener> debugRegistration;
 
 	/*
 	 * Returns the singleton for this Activator. Callers should be aware that
@@ -71,6 +74,9 @@ public class Activator implements BundleActivator {
 		platformURLConverterService = context.registerService(URLConverter.class, new PlatformURLConverter(), urlProperties);
 		adapterManagerService = context.registerService(IAdapterManager.class, AdapterManager.getDefault(), null);
 		installPlatformURLSupport();
+		Hashtable<String, String> properties = new Hashtable<>(2);
+		properties.put(DebugOptions.LISTENER_SYMBOLICNAME, PLUGIN_ID);
+		debugRegistration = context.registerService(DebugOptionsListener.class, TracingOptions.DEBUG_OPTIONS_LISTENER, properties);
 	}
 
 	private PlatformLogWriter getPlatformWriter(BundleContext context) {
@@ -282,6 +288,10 @@ public class Activator implements BundleActivator {
 			localizationTracker.close();
 			localizationTracker = null;
 		}
+		if (debugRegistration != null) {
+			debugRegistration.unregister();
+			debugRegistration = null;
+		}
 		RuntimeLog.setLogWriter(null);
 		bundleContext = null;
 		singleton = null;
diff --git a/bundles/org.eclipse.equinox.common/src/org/eclipse/core/internal/runtime/TracingOptions.java b/bundles/org.eclipse.equinox.common/src/org/eclipse/core/internal/runtime/TracingOptions.java
new file mode 100644
index 000000000..930ddd674
--- /dev/null
+++ b/bundles/org.eclipse.equinox.common/src/org/eclipse/core/internal/runtime/TracingOptions.java
@@ -0,0 +1,18 @@
+package org.eclipse.core.internal.runtime;
+
+import org.eclipse.osgi.service.debug.DebugOptions;
+import org.eclipse.osgi.service.debug.DebugOptionsListener;
+
+public class TracingOptions {
+	public static DebugOptionsListener DEBUG_OPTIONS_LISTENER = new DebugOptionsListener() {
+		@Override
+		public void optionsChanged(DebugOptions options) {
+			debug = options.getBooleanOption(Activator.PLUGIN_ID + "/debug", false); //$NON-NLS-1$
+
+			debugProgressMonitors = debug && options.getBooleanOption(Activator.PLUGIN_ID + "/progress_monitors", false); //$NON-NLS-1$
+		}
+	};
+
+	public static boolean debug;
+	public static boolean debugProgressMonitors;
+}
diff --git a/bundles/org.eclipse.equinox.common/src/org/eclipse/core/runtime/SubMonitor.java b/bundles/org.eclipse.equinox.common/src/org/eclipse/core/runtime/SubMonitor.java
index 0e8385800..6008727de 100644
--- a/bundles/org.eclipse.equinox.common/src/org/eclipse/core/runtime/SubMonitor.java
+++ b/bundles/org.eclipse.equinox.common/src/org/eclipse/core/runtime/SubMonitor.java
@@ -16,6 +16,11 @@
  *******************************************************************************/
 package org.eclipse.core.runtime;
 
+import java.util.HashSet;
+import java.util.Set;
+import org.eclipse.core.internal.runtime.RuntimeLog;
+import org.eclipse.core.internal.runtime.TracingOptions;
+
 /**
  * <p>A progress monitor that uses a given amount of work ticks from a parent monitor. This is intended as a 
  * safer, easier-to-use alternative to SubProgressMonitor. The main benefits of SubMonitor over 
@@ -357,6 +362,16 @@ public final class SubMonitor implements IProgressMonitorWithBlocking {
 	private final int flags;
 
 	/**
+	 * True iff beginTask has been called on the public interface yet.
+	 */
+	private boolean beginTaskCalled;
+
+	/**
+	 * True iff ticks have been allocated yet.
+	 */
+	private boolean ticksAllocated;
+
+	/**
 	 * May be passed as a flag to {@link #split}. Indicates that the calls
 	 * to subTask on the child should be ignored. Without this flag,
 	 * calling subTask on the child will result in a call to subTask
@@ -413,6 +428,8 @@ public final class SubMonitor implements IProgressMonitorWithBlocking {
 	 */
 	private static final int ALL_INHERITED_FLAGS = SUPPRESS_SUBTASK | SUPPRESS_ISCANCELED;
 
+	private static final Set<String> knownBuggyMethods = new HashSet<>();
+
 	/**
 	 * Creates a new SubMonitor that will report its progress via
 	 * the given RootInfo.
@@ -426,6 +443,7 @@ public final class SubMonitor implements IProgressMonitorWithBlocking {
 		totalParent = (totalWork > 0) ? totalWork : 0;
 		this.totalForChildren = availableToChildren;
 		this.flags = flags;
+		ticksAllocated = availableToChildren > 0;
 	}
 
 	/**
@@ -492,8 +510,9 @@ public final class SubMonitor implements IProgressMonitorWithBlocking {
 
 		// Optimization: if the given monitor already a SubMonitor, no conversion is necessary
 		if (monitor instanceof SubMonitor) {
-			monitor.beginTask(taskName, work);
-			return (SubMonitor) monitor;
+			SubMonitor subMonitor = (SubMonitor) monitor;
+			subMonitor.beginTaskImpl(taskName, work);
+			return subMonitor;
 		}
 
 		monitor.beginTask(taskName, MINIMUM_RESOLUTION);
@@ -531,8 +550,19 @@ public final class SubMonitor implements IProgressMonitorWithBlocking {
 	 * @return the receiver
 	 */
 	public SubMonitor setWorkRemaining(int workRemaining) {
+		if (TracingOptions.debugProgressMonitors && ticksAllocated && usedForChildren >= totalForChildren && workRemaining > 0) {
+			logProblem("Attempted to allocate ticks on a SubMonitor which had no space available. " //$NON-NLS-1$
+					+ "This may indicate that a SubMonitor was reused inappropriately (which is a bug) " //$NON-NLS-1$
+					+ "or may indicate that the caller was implementing infinite progress and overflowed " //$NON-NLS-1$
+					+ "(which may not be a bug but may require selecting a higher ratio)"); //$NON-NLS-1$
+		}
+
 		// Ensure we don't try to allocate negative ticks
-		workRemaining = Math.max(0, workRemaining);
+		if (workRemaining > 0) {
+			ticksAllocated = true;
+		} else {
+			workRemaining = 0;
+		}
 
 		// Ensure we don't cause division by zero
 		if (totalForChildren > 0 && totalParent > usedForParent) {
@@ -556,14 +586,21 @@ public final class SubMonitor implements IProgressMonitorWithBlocking {
 	 * @return ticks the number of ticks to be consumed from parent
 	 */
 	private int consume(double ticks) {
+		if (TracingOptions.debugProgressMonitors && !ticksAllocated && ticks > 0) {
+			logProblem("You must allocate ticks using beginTask or setWorkRemaining before trying to consume them"); //$NON-NLS-1$
+		}
+
 		if (totalParent == 0 || totalForChildren == 0) // this monitor has no available work to report
 			return 0;
 
 		usedForChildren += ticks;
 
-		if (usedForChildren > totalForChildren)
+		if (usedForChildren > totalForChildren) {
 			usedForChildren = totalForChildren;
-		else if (usedForChildren < 0.0)
+			if (TracingOptions.debugProgressMonitors) {
+				logProblem("This progress monitor consumed more ticks than were allocated for it."); //$NON-NLS-1$
+			}
+		} else if (usedForChildren < 0.0)
 			usedForChildren = 0.0;
 
 		int parentPosition = (int) (totalParent * usedForChildren / totalForChildren);
@@ -603,9 +640,17 @@ public final class SubMonitor implements IProgressMonitorWithBlocking {
 	 */
 	@Override
 	public void beginTask(String name, int totalWork) {
+		if (TracingOptions.debugProgressMonitors && beginTaskCalled) {
+			logProblem("beginTask was called on this instance more than once"); //$NON-NLS-1$
+		}
+		beginTaskImpl(name, totalWork);
+	}
+
+	private void beginTaskImpl(String name, int totalWork) {
 		if ((flags & SUPPRESS_BEGINTASK) == 0 && name != null)
 			root.setTaskName(name);
 		setWorkRemaining(totalWork);
+		beginTaskCalled = true;
 	}
 
 	@Override
@@ -638,6 +683,10 @@ public final class SubMonitor implements IProgressMonitorWithBlocking {
 
 	@Override
 	public void worked(int work) {
+		if (TracingOptions.debugProgressMonitors && work == 0) {
+			logProblem("Attempted to report 0 ticks of work"); //$NON-NLS-1$
+		}
+
 		internalWorked(work);
 	}
 
@@ -726,6 +775,10 @@ public final class SubMonitor implements IProgressMonitorWithBlocking {
 	 * @return new sub progress monitor that may be used in place of a new SubMonitor
 	 */
 	public SubMonitor newChild(int totalWork, int suppressFlags) {
+		if (TracingOptions.debugProgressMonitors && totalWork == 0) {
+			logProblem("Attempted to create a child without providing it with any ticks"); //$NON-NLS-1$
+		}
+
 		double totalWorkDouble = (totalWork > 0) ? totalWork : 0.0d;
 		totalWorkDouble = Math.min(totalWorkDouble, totalForChildren - usedForChildren);
 		cleanupActiveChild();
@@ -748,7 +801,7 @@ public final class SubMonitor implements IProgressMonitorWithBlocking {
 		// is no method on the child that would delegate to beginTask on the parent.
 		childFlags |= (suppressFlags & ALL_PUBLIC_FLAGS);
 
-		SubMonitor result = new SubMonitor(root, consume(totalWorkDouble), (int) totalWorkDouble, childFlags);
+		SubMonitor result = new SubMonitor(root, consume(totalWorkDouble), 0, childFlags);
 		lastSubMonitor = result;
 		return result;
 	}
@@ -944,4 +997,30 @@ public final class SubMonitor implements IProgressMonitorWithBlocking {
 			return false;
 		return o1.equals(o2);
 	}
+
+	private static String getCallerName() {
+		StackTraceElement[] stackTrace = Thread.currentThread().getStackTrace();
+
+		String ourClassName = SubMonitor.class.getCanonicalName();
+		for (int idx = 1; idx < stackTrace.length; idx++) {
+			String className = stackTrace[idx].getClassName();
+			if (className.equals(ourClassName)) {
+				continue;
+			}
+
+			return stackTrace[idx].toString();
+		}
+
+		return "Unknown"; //$NON-NLS-1$
+	}
+
+	private static void logProblem(String message) {
+		String caller = getCallerName();
+		synchronized (knownBuggyMethods) {
+			if (!knownBuggyMethods.add(caller)) {
+				return;
+			}
+		}
+		RuntimeLog.log(new Status(IStatus.WARNING, "org.eclipse.core.runtime", message, new Throwable())); //$NON-NLS-1$
+	}
 }