[303828] Instrument ServiceEventWaitor

dsf-gdb/org.eclipse.cdt.tests.dsf.gdb/.options

@@ -0,0 +1,2 @@
+org.eclipse.cdt.tests.dsf.gdb/debug = false
+org.eclipse.cdt.tests.dsf.gdb/debug/waitMetrics = false

dsf-gdb/org.eclipse.cdt.tests.dsf.gdb/src/org/eclipse/cdt/tests/dsf/gdb/framework/ServiceEventWaitor.java

@@ -12,17 +12,20 @@ package org.eclipse.cdt.tests.dsf.gdb.framework;
 
 import org.eclipse.cdt.dsf.service.DsfServiceEventHandler;
 import org.eclipse.cdt.dsf.service.DsfSession;
+import org.eclipse.cdt.tests.dsf.gdb.launching.TestsPlugin;
+import org.eclipse.core.runtime.Platform;
 
 /*
  * This class provides a way to wait for an asynchronous ServerEvent
  * to occur.  The user of this class specifies which event is of
- * interest using the proper constructor or the registerForEvent() method.
- * waitForEvent() can then be called to block until the event occurs or
- * the timeout elapses.
+ * interest . waitForEvent() can then be called to block until the event occurs or
+ * the timeout elapses. It's important that this object be created <b>before</b> 
+ * executing the debugger operation that will cause the expected event to occur, 
+ * otherwise the caller stands to miss out on the event.
  * 
- * Note that if the event occurs after regsiterForEvent() is called but
- * before waitForEvent() is called, waitForEvent() will return immediatly
- * since it will know the event has already occured.
+ * Note that if the event occurs after object construction but
+ * before waitForEvent() is called, waitForEvent() will return immediately
+ * since it will know the event has already occurred.
  */
 
 public class ServiceEventWaitor<V> {
@@ -37,26 +40,22 @@ public class ServiceEventWaitor<V> {
 	private DsfSession fSession;
     private V fEvent;
     
+    /**
+     * Trace option for wait metrics
+     */
+    private static final boolean LOG = TestsPlugin.DEBUG && "true".equals(Platform.getDebugOption("org.eclipse.cdt.tests.dsf.gdb/debug/waitMetrics"));  //$NON-NLS-1$//$NON-NLS-2$
 
-	/* Empty contructor.  registerForEvent() should be called when
-	 * this constructor is used.
-	 */
-	public ServiceEventWaitor(DsfSession session) {
-		fSession = session;
-	}
-	
-	/* Contructor that takes the eventClass as parameter.  This is a shortcut
-	 * that avoids calling registerForEvent()
+	/**
+	 * Constructor
+	 * 
+	 * @param session
+	 *            the DSF session we'll wait for an event to happen on
+	 * @param eventClass
+	 *            the event to expect
 	 */
 	public ServiceEventWaitor(DsfSession session, Class<V> eventClass)	{
-		this(session);
-		registerForEvent(eventClass);
-	}
-	
-	/* Specify which event to wait for, and add ourselves as
-	 * a listener with the session 
-	 */
-	public void registerForEvent(Class<V> eventClass) {
+		assert eventClass != null;
+		fSession = session;
 		fEventTypeClass = eventClass;
 		fEvent = null;
 		fSession.addServiceEventListener(this, null);
@@ -69,9 +68,8 @@ public class ServiceEventWaitor<V> {
 	}
 
 	/*
-	 * Block until 'timeout' or the previously specified event has been
-	 * received. The reason we don's specify the event as a parameter is that we
-	 * must be ready for the event to occur even before this method is called.
+	 * Block until 'timeout' or the expected event occurs. The expected event is
+	 * specified at construction time.
 	 * 
 	 * @param timeout the maximum time to wait in milliseconds.
 	 */
@@ -79,20 +77,61 @@ public class ServiceEventWaitor<V> {
 		if (fEventTypeClass == null) {
 			throw new Exception("Event to wait for has not been specified!");
 		}
+		
+		long startMs = System.currentTimeMillis();
+		
 		// The event might have already been received
-		if (fEvent != null) return fEvent;
-		
-		wait(timeout);
-		
 		if (fEvent == null) {
-			throw new Exception("Timed out waiting for ServiceEvent: " + fEventTypeClass.getName());
+			wait(timeout);
+			if (fEvent == null) {
+				throw new Exception("Timed out waiting for ServiceEvent: " + fEventTypeClass.getName());
+			}
 		}
+
+		long stopMs = System.currentTimeMillis();
+		
+		// Turning on trace during development gives you the following  
+		// helpful analysis, which you can use to establish reasonable timeouts,
+		// and detect poorly configured ones. The best way to use this it to 
+		// set breakpoints on the WARNING println calls.
+		if (LOG) {
+			final long duration = stopMs - startMs;
+			System.out.println("The following caller waited for " + (duration) + " milliseconds");
+			boolean print = false;
+			for (StackTraceElement frame : Thread.currentThread().getStackTrace()) {
+				if (frame.toString().startsWith("sun.reflect.NativeMethodAccessorImpl")) {
+					// ignore anything once we get into the reflection/junit portion of the stack
+					System.out.println("\t... (junit)");
+					break;
+				}
+				if (print) {
+					System.out.println("\t" + frame);
+				}
+				if (!print && frame.toString().contains("ServiceEventWaitor.waitForEvent")) {
+					// we're only interested in the call stack up to (and including) our caller					
+					print = true;
+				}
+			}
+			
+			if (timeout != WAIT_FOREVER) {
+				if (timeout/duration > 7.0) {
+					System.out.println("WARNING: Caller specified a timeout that was more than 7X what was necessary. The timeout is probably too loose.");
+				}
+				else if ((((float)(timeout - duration))/(float)duration) < 0.20) {
+					System.out.println("WARNING: Caller specified a timeout that was less than 20% above actual time. The timeout is probably too tight.");
+				}
+			}
+			else {
+				System.out.println("WARNING: Caller requested to wait forever. It should probably specify some reasonable value.");
+			}
+		}
+		
 		return fEvent;
 	}
 
 	/*
 	 * Listen to all possible events by having the base class be the parameter.
-	 * and then igure out if that event is the one we were waiting for.
+	 * and then figure out if that event is the one we were waiting for.
 	 */
 	@DsfServiceEventHandler 
 	public void eventDispatched(V event) {

dsf-gdb/org.eclipse.cdt.tests.dsf.gdb/src/org/eclipse/cdt/tests/dsf/gdb/launching/TestsPlugin.java

@@ -13,6 +13,7 @@ package org.eclipse.cdt.tests.dsf.gdb.launching;
 import java.util.MissingResourceException;
 import java.util.ResourceBundle;
 
+import org.eclipse.core.runtime.Platform;
 import org.eclipse.core.runtime.Plugin;
 import org.osgi.framework.BundleContext;
 
@@ -28,6 +29,9 @@ public class TestsPlugin extends Plugin {
 	
     public static final String PLUGIN_ID = "org.eclipse.cdt.tests.dsf.gdb"; //$NON-NLS-1$
     
+    /** Base tracing option for this plugin */
+    public static final boolean DEBUG = "true".equals(Platform.getDebugOption("org.eclipse.cdt.tests.dsf.gdb/debug"));  //$NON-NLS-1$//$NON-NLS-2$
+    
     /**
      * The constructor.
      */