Added generic tracing to the executor (bug# 159052).

plugins/org.eclipse.dd.dsf/src/org/eclipse/dd/dsf/DsfPlugin.java

@@ -45,7 +45,7 @@ public class DsfPlugin extends Plugin {
 	public void start(BundleContext context) throws Exception {
         fgBundleContext = context;
 		super.start(context);
-        DEBUG = "true".equals(Platform.getDebugOption("org.eclipse.debug.ui/debug"));  //$NON-NLS-1$//$NON-NLS-2$
+        DEBUG = "true".equals(Platform.getDebugOption("org.eclipse.dd.dsf/debug"));  //$NON-NLS-1$//$NON-NLS-2$
     }
 
 	/*

plugins/org.eclipse.dd.dsf/src/org/eclipse/dd/dsf/concurrent/DefaultDsfExecutor.java

@@ -13,11 +13,16 @@ package org.eclipse.dd.dsf.concurrent;
 import java.io.ByteArrayOutputStream;
 import java.io.IOException;
 import java.io.PrintStream;
+import java.util.HashMap;
+import java.util.Map;
+import java.util.concurrent.Callable;
 import java.util.concurrent.CancellationException;
 import java.util.concurrent.ExecutionException;
 import java.util.concurrent.Future;
+import java.util.concurrent.ScheduledFuture;
 import java.util.concurrent.ScheduledThreadPoolExecutor;
 import java.util.concurrent.ThreadFactory;
+import java.util.concurrent.TimeUnit;
 
 import org.eclipse.core.runtime.IStatus;
 import org.eclipse.core.runtime.Platform;
@@ -32,14 +37,7 @@ import org.eclipse.dd.dsf.DsfPlugin;
 public class DefaultDsfExecutor extends ScheduledThreadPoolExecutor 
     implements DsfExecutor 
 {
-    // debug tracing flags
+    /** Thread factory that creates the single thread to be used for this executor */
-    public static boolean DEBUG_EXECUTOR = false;
-    static {
-        DEBUG_EXECUTOR = DsfPlugin.DEBUG && "true".equals( //$NON-NLS-1$
-            Platform.getDebugOption("org.eclipse.dd.dsf/debug/executor")); //$NON-NLS-1$
-    }  
-
-    
     static class DsfThreadFactory implements ThreadFactory {
         Thread fThread;
         public Thread newThread(Runnable r) {
@@ -51,6 +49,11 @@ public class DefaultDsfExecutor extends ScheduledThreadPoolExecutor
 
     public DefaultDsfExecutor() {
         super(1, new DsfThreadFactory());
+        if(DEBUG_EXECUTOR || ASSERTIONS_ENABLED) {
+            // If tracing, pre-start the dispatch thread, and add it to the map.
+            prestartAllCoreThreads();
+            fThreadToExecutorMap.put(((DsfThreadFactory)getThreadFactory()).fThread, DefaultDsfExecutor.this);
+        }
     }
     
     public boolean isInExecutorThread() {
@@ -69,18 +72,238 @@ public class DefaultDsfExecutor extends ScheduledThreadPoolExecutor
                 if (e.getCause() != null) {
                     DsfPlugin.getDefault().getLog().log(new Status(
                         IStatus.ERROR, DsfPlugin.PLUGIN_ID, -1, "Uncaught exception in DSF executor thread", e.getCause()));
-                    if (DEBUG_EXECUTOR) {
+                    
+                    // Print out the stack trace to console if assertions are enabled. 
+                    if(ASSERTIONS_ENABLED) {
                         ByteArrayOutputStream outStream = new ByteArrayOutputStream(512);
                         PrintStream printStream = new PrintStream(outStream);
                         try {
                             printStream.write("Uncaught exception in session executor thread: ".getBytes());
                         } catch (IOException e2) {}
                         e.getCause().printStackTrace(new PrintStream(outStream));
-                        DsfPlugin.debug(outStream.toString());
+                        System.err.println(outStream.toString());
                     }
                 }
             }
         }
     }
 
+    
+    //
+    // Utilities used for tracing.
+    //
+    static boolean DEBUG_EXECUTOR = false;
+    static boolean ASSERTIONS_ENABLED = false;
+    static {
+        DEBUG_EXECUTOR = DsfPlugin.DEBUG && "true".equals( //$NON-NLS-1$
+            Platform.getDebugOption("org.eclipse.dd.dsf/debug/executor")); //$NON-NLS-1$
+        assert ASSERTIONS_ENABLED = true;
+    }  
+
+    /** 
+     * This map is used by DsfRunnable/DsfQuery/DsfCallable to track by which executor
+     * an executable object was created.
+     * <br>Note: Only used when tracing. 
+     */
+    static Map<Thread, DefaultDsfExecutor> fThreadToExecutorMap = new HashMap<Thread, DefaultDsfExecutor>();
+    
+    /** 
+     * Currently executing runnable/callable.
+     * <br>Note: Only used when tracing. 
+     */
+    TracingWrapper fCurrentlyExecuting;
+    
+    /** 
+     * Counter number saved by each tracing runnable when executed 
+     * <br>Note: Only used when tracing. 
+     */
+    int fSequenceCounter;
+
+    /** 
+     * Wrapper for runnables/callables, is used to store tracing information 
+     * <br>Note: Only used when tracing. 
+     */
+    abstract class TracingWrapper {
+        /** Sequence number of this runnable/callable */
+        int fSequenceNumber = -1; 
+        
+        /** Trace of where the runnable/callable was submitted to the executor */
+        StackTraceElement[] fSubmittedAt = null; 
+        
+        /** Reference to the runnable/callable that submitted this runnable/callable to the executor */
+        TracingWrapper fSubmittedBy = null;
+
+        /**
+         * @param offset the number of items in the stack trace not to be printed
+         */
+        TracingWrapper(int offset) {
+            StackTraceElement[] stackTrace = Thread.currentThread().getStackTrace();
+            fSubmittedAt = new StackTraceElement[stackTrace.length - offset]; 
+            System.arraycopy(stackTrace, offset - 1, fSubmittedAt, 0, fSubmittedAt.length);
+            if (isInExecutorThread() &&  fCurrentlyExecuting != null) {
+                fSubmittedBy = fCurrentlyExecuting;
+            }
+        }
+        
+        void traceExecution() {
+            fSequenceNumber = fSequenceCounter++;
+            fCurrentlyExecuting = this;
+
+            // Write to console only if tracing is enabled (as opposed to tracing or assertions).
+            if (DEBUG_EXECUTOR) {
+                StringBuilder traceBuilder = new StringBuilder();
+    
+                // Record the time
+                long time = System.currentTimeMillis();
+                long seconds = (time / 1000) % 1000;
+                if (seconds < 100) traceBuilder.append('0');
+                if (seconds < 10) traceBuilder.append('0');
+                traceBuilder.append(seconds);
+                traceBuilder.append(',');
+                long millis = time % 1000;
+                if (millis < 100) traceBuilder.append('0');
+                if (millis < 10) traceBuilder.append('0');
+                traceBuilder.append(millis);
+                traceBuilder.append(' ');
+    
+                // Record the executor #
+                traceBuilder.append('#');
+                traceBuilder.append(fSequenceNumber);
+                traceBuilder.append(' ');
+    
+                // Append executable class name
+                traceBuilder.append(getExecutable().getClass().getName());
+                if (getExecutable() instanceof DsfExecutable) {
+                    DsfExecutable dsfExecutable = (DsfExecutable)getExecutable(); 
+                    if (dsfExecutable.fCreatedAt != null || dsfExecutable.fCreatedBy != null) {
+                        traceBuilder.append("\n        Created  ");
+                        if (dsfExecutable.fCreatedBy != null) {
+                            traceBuilder.append(" by #");
+                            traceBuilder.append(dsfExecutable.fCreatedBy.fSequenceNumber);
+                        }
+                        if (dsfExecutable.fCreatedAt != null) {
+                            traceBuilder.append(" at ");
+                            traceBuilder.append(dsfExecutable.fCreatedAt[0].toString());
+                        }   
+                    }
+                }
+    
+                // Submitted info
+                traceBuilder.append("\n        ");
+                traceBuilder.append("Submitted");
+                if (fSubmittedBy != null) {
+                    traceBuilder.append(" by #");
+                    traceBuilder.append(fSubmittedBy.fSequenceNumber);
+                }
+                traceBuilder.append(" at ");
+                traceBuilder.append(fSubmittedAt[0].toString());
+                
+                // Finally, the executable's toString().
+                traceBuilder.append("\n        ");
+                traceBuilder.append(getExecutable().toString());
+                
+                // Finally write out to console
+                DsfPlugin.debug(traceBuilder.toString());
+            }
+        }
+
+        abstract protected Object getExecutable();
+    }
+    
+    class TracingWrapperRunnable extends TracingWrapper implements Runnable {
+        final Runnable fRunnable;
+        public TracingWrapperRunnable(Runnable runnable, int offset) {
+            super(offset);
+            fRunnable = runnable;
+        }
+
+        protected Object getExecutable() { return fRunnable; }
+        
+        public void run() {
+            traceExecution();
+            fRunnable.run(); 
+        }
+    }
+    
+    public class TracingWrapperCallable<T> extends TracingWrapper implements Callable<T> {
+        final Callable<T> fCallable;
+        public TracingWrapperCallable(Callable<T> callable, int offset) {
+            super(offset);
+            fCallable = callable;
+        }
+
+        protected Object getExecutable() { return fCallable; }
+
+        public T call() throws Exception {
+            traceExecution();
+            return fCallable.call();
+        }
+    }
+
+    @Override
+    public <V> ScheduledFuture<V> schedule(Callable<V> callable, long delay, TimeUnit unit) {
+        if(DEBUG_EXECUTOR || ASSERTIONS_ENABLED) {
+            if ( !(callable instanceof TracingWrapper) ) {
+                callable = new TracingWrapperCallable<V>(callable, 6);
+            }
+        }
+        return super.schedule(callable, delay, unit);
+    }
+     @Override
+     public ScheduledFuture<?> schedule(Runnable command, long delay, TimeUnit unit) {
+         if(DEBUG_EXECUTOR || ASSERTIONS_ENABLED) {
+             if ( !(command instanceof TracingWrapper) ) {
+                 command = new TracingWrapperRunnable(command, 6);
+             }
+         }
+         return super.schedule(command, delay, unit);
+    }
+
+    @Override
+    public ScheduledFuture<?> scheduleAtFixedRate(Runnable command, long initialDelay, long period, TimeUnit unit) {
+        if(DEBUG_EXECUTOR || ASSERTIONS_ENABLED) {
+            command = new TracingWrapperRunnable(command, 6);
+        }
+        return super.scheduleAtFixedRate(command, initialDelay, period, unit);
+    }
+
+    @Override
+    public ScheduledFuture<?> scheduleWithFixedDelay(Runnable command, long initialDelay, long delay, TimeUnit unit) {
+        if(DEBUG_EXECUTOR || ASSERTIONS_ENABLED) {
+            command = new TracingWrapperRunnable(command, 6);
+        }
+        return super.scheduleWithFixedDelay(command, initialDelay, delay, unit);
+    }
+
+    @Override
+    public void execute(Runnable command) {
+        if(DEBUG_EXECUTOR || ASSERTIONS_ENABLED) {
+            command = new TracingWrapperRunnable(command, 6);
+        }
+        super.execute(command);
+    }     
+    
+    @Override
+    public Future<?> submit(Runnable command) {
+        if(DEBUG_EXECUTOR || ASSERTIONS_ENABLED) {
+            command = new TracingWrapperRunnable(command, 6);
+        }
+        return super.submit(command);
+    }
+    
+    @Override
+    public <T> Future<T> submit(Callable<T> callable) {
+        if(DEBUG_EXECUTOR || ASSERTIONS_ENABLED) {
+            callable = new TracingWrapperCallable<T>(callable, 6);
+        }
+        return super.submit(callable);
+    }
+    
+    @Override
+    public <T> Future<T> submit(Runnable command, T result) {
+        if(DEBUG_EXECUTOR || ASSERTIONS_ENABLED) {
+            command = new TracingWrapperRunnable(command, 6);
+        }
+        return super.submit(command, result);
+    }
 }

plugins/org.eclipse.dd.dsf/src/org/eclipse/dd/dsf/concurrent/Done.java

@@ -63,4 +63,8 @@ abstract public class Done extends DsfRunnable {
         } 
         return false;
     }
+    
+    public String toString() {
+        return getStatus().toString();
+    }
 }

plugins/org.eclipse.dd.dsf/src/org/eclipse/dd/dsf/concurrent/DsfExecutable.java

@@ -0,0 +1,62 @@
+/*******************************************************************************
+ * Copyright (c) 2006 Wind River Systems 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
+ * http://www.eclipse.org/legal/epl-v10.html
+ * 
+ * Contributors:
+ *     Wind River Systems - initial API and implementation
+ *******************************************************************************/
+package org.eclipse.dd.dsf.concurrent;
+
+import java.util.HashSet;
+import java.util.Set;
+
+/**
+ * Base class for DSF-instrumented alternative to the Runnable/Callable interfaces.
+ * <p>
+ * While it is perfectly fine for clients to call the DSF executor with
+ * an object only implementing the Runnable/Callable interface, the DsfExecutable
+ * contains fields and methods that used for debugging and tracing when 
+ * tracing is enabled.
+ */
+public class DsfExecutable {
+    final StackTraceElement[]  fCreatedAt;
+    final DefaultDsfExecutor.TracingWrapper fCreatedBy;
+
+    @SuppressWarnings("unchecked")
+    public DsfExecutable() {
+        // Use assertion flag (-ea) to jre to avoid affecting performance when not debugging.
+        boolean assertsEnabled = false;
+        assert assertsEnabled = true;
+        if (assertsEnabled || DefaultDsfExecutor.DEBUG_EXECUTOR) {
+            // Find the runnable/callable that is currently running.
+            DefaultDsfExecutor executor = DefaultDsfExecutor.fThreadToExecutorMap.get(Thread.currentThread()); 
+            if (executor != null) {
+                fCreatedBy = executor.fCurrentlyExecuting;
+            } else {
+                fCreatedBy = null;
+            }
+            
+            // Get the stack trace and find the first method that is not a 
+            // constructor of this object. 
+            StackTraceElement[] stackTrace = Thread.currentThread().getStackTrace();
+            Class thisClass = getClass();
+            Set<String> classNamesSet = new HashSet<String>();
+            while(thisClass != null) {
+                classNamesSet.add(thisClass.getName());
+                thisClass = thisClass.getSuperclass();
+            }
+            int i;
+            for (i = 3; i < stackTrace.length; i++) {
+                if ( !classNamesSet.contains(stackTrace[i].getClassName()) ) break;
+            }
+            fCreatedAt = new StackTraceElement[stackTrace.length - i]; 
+            System.arraycopy(stackTrace, i, fCreatedAt, 0, fCreatedAt.length);
+        } else {
+            fCreatedAt = null;
+            fCreatedBy = null;
+        }
+    }        
+}

plugins/org.eclipse.dd.dsf/src/org/eclipse/dd/dsf/concurrent/DsfRunnable.java

@@ -10,6 +10,7 @@
  *******************************************************************************/
 package org.eclipse.dd.dsf.concurrent;
 
+
 /**
  * A DSF-instrumented alternative to the Runnable interface.    
  * <p>
@@ -18,45 +19,5 @@ package org.eclipse.dd.dsf.concurrent;
  * contains fields and methods that used for debugging and tracing when 
  * tracing is enabled.
  */
-abstract public class DsfRunnable implements Runnable {
+abstract public class DsfRunnable extends DsfExecutable implements Runnable {
-    private StackTraceElement []  fStackTrace = null; 
-    private Runnable fSubmittedBy = null;
-    
-    public DsfRunnable() {
-        // Use assertion flag (-ea) to jre to avoid affecting performance when not debugging.
-        boolean assertsEnabled = false;
-        assert assertsEnabled = true;
-        if (assertsEnabled || DefaultDsfExecutor.DEBUG_EXECUTOR) {
-            fStackTrace = Thread.currentThread().getStackTrace();
-        }
-    }
-    
-    public  String toString () {
-        StringBuilder builder = new  StringBuilder() ;
-        // If assertions are not turned on.
-        builder.append(super.toString());
-        if (fStackTrace != null) {
-            builder.append ( "\n\tCreated at" ) ;
-            
-            // ommit the first elements in the stack trace
-            for  (int i = 3; i < fStackTrace.length && i < 13; i++) {
-                if (i > 3) builder.append ( "\tat " ) ;
-                builder.append( fStackTrace [ i ] .toString ()) ;
-                builder.append( "\n" ) ;
-            }
-            if (fStackTrace.length > 13) {
-                builder.append("\t at ...");
-            }
-        }
-        if (fSubmittedBy != null) {
-            builder.append("Submitted by \n");
-            builder.append(fSubmittedBy.toString());
-        }
-        
-        return  builder.toString();
-    } 
-    
-    void setSubmittedBy(Runnable runnable) {
-        fSubmittedBy = runnable;
-    }
 }

plugins/org.eclipse.dd.dsf/src/org/eclipse/dd/dsf/concurrent/GetDataDone.java

@@ -30,4 +30,12 @@ public abstract class GetDataDone<V> extends Done {
      * Returns the data value, null if not set.
      */
     public V getData() { return fData; }
+    
+    public String toString() { 
+        if (getData() != null) {
+            return getData().toString();
+        } else {
+            return super.toString();
+        }
+    }
 }