[Swift-commit] r6023 - in trunk/src/org/griphyn/vdl: karajan/lib karajan/lib/swiftscript mapping util

hategan at ci.uchicago.edu hategan at ci.uchicago.edu
Fri Nov 9 23:43:55 CST 2012


Author: hategan
Date: 2012-11-09 23:43:55 -0600 (Fri, 09 Nov 2012)
New Revision: 6023

Added:
   trunk/src/org/griphyn/vdl/karajan/lib/Tracer.java
Modified:
   trunk/src/org/griphyn/vdl/karajan/lib/InfiniteCountingWhile.java
   trunk/src/org/griphyn/vdl/karajan/lib/New.java
   trunk/src/org/griphyn/vdl/karajan/lib/SetFieldValue.java
   trunk/src/org/griphyn/vdl/karajan/lib/Stagein.java
   trunk/src/org/griphyn/vdl/karajan/lib/ThrottledParallelFor.java
   trunk/src/org/griphyn/vdl/karajan/lib/UnitStart.java
   trunk/src/org/griphyn/vdl/karajan/lib/swiftscript/ReadData.java
   trunk/src/org/griphyn/vdl/mapping/MappingParamSet.java
   trunk/src/org/griphyn/vdl/mapping/RootArrayDataNode.java
   trunk/src/org/griphyn/vdl/mapping/RootDataNode.java
   trunk/src/org/griphyn/vdl/util/VDL2Config.java
   trunk/src/org/griphyn/vdl/util/VDL2ConfigProperties.java
Log:
added tracing

Modified: trunk/src/org/griphyn/vdl/karajan/lib/InfiniteCountingWhile.java
===================================================================
--- trunk/src/org/griphyn/vdl/karajan/lib/InfiniteCountingWhile.java	2012-11-10 05:42:36 UTC (rev 6022)
+++ trunk/src/org/griphyn/vdl/karajan/lib/InfiniteCountingWhile.java	2012-11-10 05:43:55 UTC (rev 6023)
@@ -34,17 +34,29 @@
     
     public static final String COUNTER_NAME = "$";
     public static final Arg.Positional VAR = new Arg.Positional("var");
+    
+    private Tracer tracer;
 
 	public InfiniteCountingWhile() {
 		setOptimize(false);
 	}
+	
+	@Override
+    protected void initializeStatic() {
+        super.initializeStatic();
+        tracer = Tracer.getTracer(this);
+    }
 
-	public void pre(VariableStack stack) throws ExecutionException {
+    public void pre(VariableStack stack) throws ExecutionException {
 		ThreadingContext tc = (ThreadingContext)stack.getVar("#thread");
 		stack.setVar("#iteratethread", tc);
 		stack.setVar("#thread", tc.split(0));
 		stack.setVar(COUNTER_NAME, Collections.singletonList(0));
-		stack.setVar((String) VAR.getStatic(this), new RootDataNode(Types.INT, 0));
+		String var = (String) VAR.getStatic(this);
+		if (tracer.isEnabled()) {
+		    tracer.trace(tc.toString(), var + " = 0");
+		}
+		stack.setVar(var, new RootDataNode(Types.INT, 0));
 		super.pre(stack);
 	}
 
@@ -69,9 +81,14 @@
             int i = c.get(0).intValue();
             i++;
             ThreadingContext tc = (ThreadingContext)stack.getVar("#iteratethread");
-            stack.setVar("#thread", tc.split(i));
+            ThreadingContext ntc = tc.split(i);
+            stack.setVar("#thread", ntc);
             stack.setVar(COUNTER_NAME, Collections.singletonList(i));
-            stack.setVar((String) VAR.getStatic(this), new RootDataNode(Types.INT, i));
+            String var = (String) VAR.getStatic(this);
+            if (tracer.isEnabled()) {
+                tracer.trace(ntc.toString(), var + " = " + i);
+            }
+            stack.setVar(var, new RootDataNode(Types.INT, i));
 		}
 		if (index >= elementCount()) {
 			// starting new iteration

Modified: trunk/src/org/griphyn/vdl/karajan/lib/New.java
===================================================================
--- trunk/src/org/griphyn/vdl/karajan/lib/New.java	2012-11-10 05:42:36 UTC (rev 6022)
+++ trunk/src/org/griphyn/vdl/karajan/lib/New.java	2012-11-10 05:43:55 UTC (rev 6023)
@@ -55,8 +55,16 @@
 		setArguments(New.class,
 				new Arg[] { OA_TYPE, OA_MAPPING, OA_VALUE, OA_DBGNAME, OA_WAITFOR});
 	}
+	
+	private Tracer tracer;
 
-	public Object function(VariableStack stack) throws ExecutionException {
+	@Override
+    protected void initializeStatic() {
+        super.initializeStatic();
+        tracer = Tracer.getTracer(this);
+    }
+
+    public Object function(VariableStack stack) throws ExecutionException {
 		String typename = TypeUtil.toString(OA_TYPE.getValue(stack));
 		Object value = OA_VALUE.getValue(stack);
 		@SuppressWarnings("unchecked")
@@ -105,6 +113,9 @@
 			}
 			DSHandle handle;
 			if (typename.equals("external")) {
+			    if (tracer.isEnabled()) {
+			        tracer.trace(threadPrefix, dbgname + " = external");
+			    }
 				handle = new ExternalDataNode();
 			}
 			else if (type.isArray()) {
@@ -112,12 +123,18 @@
 				handle = new RootArrayDataNode(type);
 				if (value != null) {
 					if (value instanceof RootArrayDataNode) {
+					    if (tracer.isEnabled()) {
+					        tracer.trace(threadPrefix, dbgname + " = " + Tracer.getVarName((RootDataNode) value));
+					    }
 						handle = (RootArrayDataNode) value;
 					}
 					else {
 						if (!(value instanceof List)) {
 							throw new ExecutionException("An array variable can only be initialized with a list of values");
 						}
+						if (tracer.isEnabled()) {
+                            tracer.trace(threadPrefix, dbgname + " = " + formatList((List<?>) value));
+                        }
 						int index = 0;
 						Iterator<?> i = ((List<?>) value).iterator();
 						while (i.hasNext()) {
@@ -137,18 +154,34 @@
 					}
 					handle.closeShallow();
 				}
+				else {
+				    if (tracer.isEnabled()) {
+				        tracer.trace(threadPrefix, dbgname);
+                    }
+				}
 
 				handle.init(mps);
 			}
 			else if (value instanceof DSHandle) {
+			    if (tracer.isEnabled()) {
+			        tracer.trace(threadPrefix, dbgname + " = " + Tracer.getVarName((DSHandle) value));
+                }
 				handle = (DSHandle) value;
 			}
 			else {
 				handle = new RootDataNode(type);
 				handle.init(mps);
 				if (value != null) {
+				    if (tracer.isEnabled()) {
+				        tracer.trace(threadPrefix, dbgname + " = " + value);
+				    }
 					handle.setValue(internalValue(type, value));
 				}
+				else {
+				    if (tracer.isEnabled()) {
+                        tracer.trace(threadPrefix, dbgname + formatMPS(mps));
+                    }
+				}
 			}
 			
 			if (AbstractDataNode.provenance && logger.isDebugEnabled()) {
@@ -160,4 +193,55 @@
 			throw new ExecutionException(e);
 		}
 	}
+
+    private String formatMPS(MappingParamSet mps) {
+        Object desc = mps.get(MappingParam.SWIFT_DESCRIPTOR);
+        if (desc == null) {
+            return "";
+        }
+        StringBuilder sb = new StringBuilder();
+        sb.append(" <");
+        sb.append(desc);
+        sb.append("; ");
+        boolean first = true;
+        for (String name : mps.names()) {
+        	if (name.indexOf('#') >= 0) {
+        		// skip internal parameters
+        		continue;
+        	}
+            if (first) {
+                first = false;
+            }
+            else {
+                sb.append(", ");
+            }
+            sb.append(name);
+            sb.append(" = \"");
+            sb.append(Tracer.unwrapHandle(mps._get(name)));
+            sb.append("\"");
+        }
+        sb.append('>');
+        return sb.toString();
+    }
+
+    private String formatList(List<?> value) {
+        StringBuilder sb = new StringBuilder();
+        sb.append('[');
+        unfoldList(value, sb);
+        sb.append(']');
+        return sb.toString();
+    }
+
+    private void unfoldList(List<?> value, StringBuilder sb) {
+        boolean first = true;
+        for (Object v : value) {
+            if (first) {
+                first = false;
+            }
+            else {
+                sb.append(", ");
+            }
+            sb.append(v);
+        }
+    }
 }

Modified: trunk/src/org/griphyn/vdl/karajan/lib/SetFieldValue.java
===================================================================
--- trunk/src/org/griphyn/vdl/karajan/lib/SetFieldValue.java	2012-11-10 05:42:36 UTC (rev 6022)
+++ trunk/src/org/griphyn/vdl/karajan/lib/SetFieldValue.java	2012-11-10 05:43:55 UTC (rev 6023)
@@ -26,10 +26,15 @@
 
 import org.apache.log4j.Logger;
 import org.globus.cog.karajan.arguments.Arg;
+import org.globus.cog.karajan.stack.VariableNotFoundException;
 import org.globus.cog.karajan.stack.VariableStack;
+import org.globus.cog.karajan.util.ThreadingContext;
 import org.globus.cog.karajan.workflow.ExecutionException;
+import org.globus.cog.karajan.workflow.futures.Future;
 import org.globus.cog.karajan.workflow.futures.FutureFault;
 import org.globus.cog.karajan.workflow.futures.FutureNotYetAvailable;
+import org.griphyn.vdl.karajan.DSHandleFutureWrapper;
+import org.griphyn.vdl.karajan.FutureWrapper;
 import org.griphyn.vdl.karajan.Pair;
 import org.griphyn.vdl.karajan.PairIterator;
 import org.griphyn.vdl.karajan.WaitingThreadsMonitor;
@@ -37,7 +42,6 @@
 import org.griphyn.vdl.mapping.DSHandle;
 import org.griphyn.vdl.mapping.InvalidPathException;
 import org.griphyn.vdl.mapping.Mapper;
-import org.griphyn.vdl.mapping.MappingParam;
 import org.griphyn.vdl.mapping.Path;
 import org.griphyn.vdl.type.Type;
 
@@ -51,8 +55,15 @@
 	}
 	
 	private String src, dest;
+	private Tracer tracer;
 
-	public Object function(VariableStack stack) throws ExecutionException {
+	@Override
+    protected void initializeStatic() {
+        super.initializeStatic();
+        tracer = Tracer.getTracer(this);
+    }
+
+    public Object function(VariableStack stack) throws ExecutionException {
 		DSHandle var = (DSHandle) PA_VAR.getValue(stack);
 		try {
 		    Path path = parsePath(OA_PATH.getValue(stack), stack);
@@ -60,11 +71,13 @@
 			AbstractDataNode value = (AbstractDataNode) PA_VALUE.getValue(stack);
 			
 			if (src == null) {
-			    dest = getVarName(var);
-			    src = getVarName(value);
+			    dest = Tracer.getVarName(var);
+			    src = Tracer.getVarName(value);
 			}
 			
-			log(leaf, value);
+			if (tracer.isEnabled()) {
+			    log(leaf, value, stack);
+			}
 			    
             // TODO want to do a type check here, for runtime type checking
             // and pull out the appropriate internal value from value if it
@@ -76,6 +89,9 @@
 			return null;
 		}
 		catch (FutureFault f) {
+		    if (tracer.isEnabled()) {
+		        tracer.trace(stack, var + " waiting for " + Tracer.getFutureName(f.getFuture()));
+		    }
 		    WaitingThreadsMonitor.addOutput(stack, Collections.singletonList(var));
 			throw f;
 		}
@@ -84,56 +100,10 @@
 		}
 	}
 
-	private String getVarName(DSHandle var) {
-	    String name = var.getRoot().getParam(MappingParam.SWIFT_DBGNAME);
-        if (var == var.getRoot()) {
-            return name;
-        }
-        else {
-            Path p = var.getPathFromRoot();
-            if (p.isArrayIndex(0)) {
-                return name + var.getPathFromRoot();
-            }
-            else {
-                return name + "." + var.getPathFromRoot();
-            }
-        }
+    private void log(DSHandle leaf, DSHandle value, VariableStack stack) throws VariableNotFoundException {
+        tracer.trace(stack, dest + " = " + Tracer.unwrapHandle(value));
     }
 
-    private void log(DSHandle leaf, DSHandle value) {
-	    if (logger.isDebugEnabled()) {
-	        logger.debug("Setting " + leaf + " to " + value);
-	    }
-	    else if (logger.isInfoEnabled()) {
-	        if (leaf instanceof AbstractDataNode) {
-	            AbstractDataNode data = (AbstractDataNode) leaf;
-	            Path path = data.getPathFromRoot();
-	            String p;
-	            if (path.isEmpty()) {
-	                p = "";
-	            }
-	            else if (path.isArrayIndex(0)) {
-	                p = path.toString();
-	            }
-	            else {
-	                p = "." + path.toString();
-	            }
-	            String name = data.getDisplayableName() + p;
-	            if (value.getType().isArray()) {
-	                if (logger.isInfoEnabled()) {
-	                    logger.info("Set: " + name + "=" + 
-                                unpackHandles(value, value.getArrayValue()));
-	                }
-	            }
-	            else {
-	                if (logger.isInfoEnabled()) {
-	                    logger.info("Set: " + name + "=" + value.getValue());
-	                }
-	            }
-	        }
-	    }
-    }
-
 	String unpackHandles(DSHandle handle, Map<Comparable<?>, DSHandle> handles) { 
 	    StringBuilder sb = new StringBuilder();
 	    sb.append("{");

Modified: trunk/src/org/griphyn/vdl/karajan/lib/Stagein.java
===================================================================
--- trunk/src/org/griphyn/vdl/karajan/lib/Stagein.java	2012-11-10 05:42:36 UTC (rev 6022)
+++ trunk/src/org/griphyn/vdl/karajan/lib/Stagein.java	2012-11-10 05:43:55 UTC (rev 6023)
@@ -30,6 +30,8 @@
 import org.globus.cog.karajan.stack.VariableStack;
 import org.globus.cog.karajan.workflow.ExecutionException;
 import org.globus.cog.karajan.workflow.futures.FutureFault;
+import org.globus.cog.karajan.workflow.nodes.FlowNode;
+import org.griphyn.vdl.engine.Karajan;
 import org.griphyn.vdl.mapping.AbstractDataNode;
 import org.griphyn.vdl.mapping.DSHandle;
 import org.griphyn.vdl.mapping.DependentException;
@@ -42,10 +44,21 @@
     public static final Arg VAR = new Arg.Positional("var");
     
     public static final Channel STAGEIN = new Channel("stagein");
+    
+    private Tracer tracer; 
+    private String procName;
 
     static {
         setArguments(Stagein.class, new Arg[] { VAR });
     }
+    
+    @Override
+    protected void initializeStatic() {
+        super.initializeStatic();
+        FlowNode def = (FlowNode) getParent().getParent();
+        procName = Karajan.demangle(def.getTextualName());
+        tracer = Tracer.getTracer(def, "APPCALL");
+    }
 
     private boolean isPrimitive(DSHandle var) {
         return (var instanceof AbstractDataNode && ((AbstractDataNode) var)
@@ -61,7 +74,11 @@
                 Collection<Path> fp = var.getFringePaths();
                 try {
                     for (Path p : fp) {
-                    	((AbstractDataNode) var.getField(p)).waitFor();
+                        AbstractDataNode n = (AbstractDataNode) var.getField(p);
+                    	n.waitFor();
+                    	if (tracer.isEnabled()) {
+                    	    tracer.trace(stack, procName + " available " + Tracer.getVarName(n));
+                    	}
                     }
                 }
                 catch (DependentException e) {
@@ -72,6 +89,9 @@
                 }
             }
             catch (FutureFault f) {
+                if (tracer.isEnabled()) {
+                    tracer.trace(stack, procName + " wait " + Tracer.getFutureName(f.getFuture()));
+                }
                 throw f;
             }
             catch (MappingDependentException e) {
@@ -90,7 +110,18 @@
         }
         else {
             // we still wait until the primitive value is there
-            var.waitFor();
+            if (tracer.isEnabled()) {
+                try {
+                    var.waitFor();
+                }
+                catch (FutureFault f) {
+                    tracer.trace(stack, procName + " waiting for " + Tracer.getFutureName(f.getFuture()));
+                    throw f;
+                }
+            }
+            else {
+                var.waitFor();
+            }
         }
         return null;
     }

Modified: trunk/src/org/griphyn/vdl/karajan/lib/ThrottledParallelFor.java
===================================================================
--- trunk/src/org/griphyn/vdl/karajan/lib/ThrottledParallelFor.java	2012-11-10 05:42:36 UTC (rev 6022)
+++ trunk/src/org/griphyn/vdl/karajan/lib/ThrottledParallelFor.java	2012-11-10 05:43:55 UTC (rev 6023)
@@ -38,6 +38,8 @@
 import org.globus.cog.karajan.workflow.futures.FutureListener;
 import org.globus.cog.karajan.workflow.futures.ListenerStackPair;
 import org.globus.cog.karajan.workflow.nodes.AbstractParallelIterator;
+import org.griphyn.vdl.karajan.Pair;
+import org.griphyn.vdl.mapping.DSHandle;
 import org.griphyn.vdl.util.VDL2Config;
 
 public class ThrottledParallelFor extends AbstractParallelIterator {
@@ -57,10 +59,24 @@
 	public static final String THREAD_COUNT = "#threadcount";
 
 	private int maxThreadCount = -1;
+	private Tracer forTracer, iterationTracer;
+	private String kvar, vvar;
+	
+    @Override
+    protected void initializeStatic() {
+        super.initializeStatic();
+        forTracer = Tracer.getTracer(this, "FOREACH");
+        iterationTracer = Tracer.getTracer(this, "ITERATION");
+        kvar = (String) getProperty("_kvar");
+        vvar = (String) getProperty("_vvar");
+    }
 
     protected void partialArgumentsEvaluated(VariableStack stack)
             throws ExecutionException {
         stack.setVar("selfclose", A_SELF_CLOSE.getValue(stack));
+        if (forTracer.isEnabled()) {
+            forTracer.trace(ThreadingContext.get(stack).toString());
+        }
         super.partialArgumentsEvaluated(stack);
     }
 
@@ -96,11 +112,15 @@
     		    for (; j < available && i.hasNext(); j++) {
     		        VariableStack copy = stack.copy();
                     copy.enter();
-                    ThreadingContext.set(copy, ThreadingContext.get(copy).split(
-                            i.current()));
+                    ThreadingContext ntc = ThreadingContext.get(copy).split(i.current());
+                    ThreadingContext.set(copy, ntc);
                     setIndex(copy, getArgCount());
                     setArgsDone(copy);
-                    copy.setVar(var.getName(), i.next());
+                    Object value = i.next();
+                    if (iterationTracer.isEnabled()) {
+                        iterationTracer.trace(ntc.toString(), unwrap(value));
+                    }
+                    copy.setVar(var.getName(), value);
                     startElement(getArgCount(), copy);
     		    }
 		    }
@@ -137,7 +157,22 @@
 		}
 	}
 	
-	public void failed(VariableStack stack, ExecutionException e) throws ExecutionException {
+	private Object unwrap(Object value) {
+        if (value instanceof Pair) {
+            Pair p = (Pair) value;
+            if (kvar != null) {
+                return kvar + "=" + p.get(0) + ", " + vvar + "=" + Tracer.unwrapHandle(p.get(1));
+            }
+            else {
+                return vvar + "=" + Tracer.unwrapHandle(p.get(1));
+            }
+        }
+        else {
+            return "!";
+        }
+    }
+
+    public void failed(VariableStack stack, ExecutionException e) throws ExecutionException {
         if (!testAndSetChildFailed(stack)) {
             if (stack.parentFrame().isDefined(VAR)) {
                 stack.leave();

Added: trunk/src/org/griphyn/vdl/karajan/lib/Tracer.java
===================================================================
--- trunk/src/org/griphyn/vdl/karajan/lib/Tracer.java	                        (rev 0)
+++ trunk/src/org/griphyn/vdl/karajan/lib/Tracer.java	2012-11-10 05:43:55 UTC (rev 6023)
@@ -0,0 +1,294 @@
+//----------------------------------------------------------------------
+//This code is developed as part of the Java CoG Kit project
+//The terms of the license can be found at http://www.cogkit.org/license
+//This message may not be removed or altered.
+//----------------------------------------------------------------------
+
+/*
+ * Created on Nov 9, 2012
+ */
+package org.griphyn.vdl.karajan.lib;
+
+import java.io.IOException;
+import java.util.HashMap;
+import java.util.Map;
+
+import org.apache.log4j.Logger;
+import org.globus.cog.karajan.stack.VariableNotFoundException;
+import org.globus.cog.karajan.stack.VariableStack;
+import org.globus.cog.karajan.util.ThreadingContext;
+import org.globus.cog.karajan.workflow.futures.Future;
+import org.globus.cog.karajan.workflow.nodes.FlowElement;
+import org.globus.cog.karajan.workflow.nodes.FlowNode;
+import org.griphyn.vdl.engine.Karajan;
+import org.griphyn.vdl.karajan.FutureWrapper;
+import org.griphyn.vdl.mapping.AbstractDataNode;
+import org.griphyn.vdl.mapping.DSHandle;
+import org.griphyn.vdl.mapping.Mapper;
+import org.griphyn.vdl.mapping.Path;
+import org.griphyn.vdl.type.Types;
+import org.griphyn.vdl.util.VDL2Config;
+
+public class Tracer {
+    public static final Logger logger = Logger.getLogger("TRACE");
+    private static boolean globalTracingEnabled;
+    private static final Map<String, String> NAME_MAPPINGS;
+    private ThreadLocal<String> thread = new ThreadLocal<String>();
+    
+    static {
+        try {
+            globalTracingEnabled = VDL2Config.getConfig().isTracingEnabled();
+        }
+        catch (IOException e) {
+            globalTracingEnabled = false;
+        }
+        NAME_MAPPINGS = new HashMap<String, String>();
+        NAME_MAPPINGS.put("assignment", "ASSIGN");
+        NAME_MAPPINGS.put("iterate", "ITERATE");
+        NAME_MAPPINGS.put("vdl:new", "DECLARE");
+    }
+    
+    private final String source;
+    private final boolean enabled;
+    
+    private Tracer(boolean enabled) {
+        source = null;
+        this.enabled = enabled;
+    }
+    
+    private Tracer(FlowNode fe, String name) {
+        source = buildSource(fe, name);
+        if (source == null) {
+            enabled = false;
+        }
+        else {
+            enabled = true;
+        }
+    }
+    
+    private Tracer(String line, String name) {
+        source = buildSource(line, name);
+        enabled = true;
+    }
+    
+    private Tracer(String name) {
+        source = name;
+        enabled = true;
+    }
+    
+    private Tracer(FlowNode fe) {
+        this(fe, null);
+    }
+    
+    private String buildSource(FlowNode fe, String name) {
+        String line = findLine(fe);
+        if (line == null) {
+            return null;
+        }
+        if (name == null) {
+            name = getType(fe);
+        }
+        return buildSource(line, name);      
+    }
+
+    private String buildSource(String line, String name) {
+        StringBuilder sb = new StringBuilder();
+        sb.append(name);
+        sb.append(", line ");
+        sb.append(line);
+        return sb.toString();
+    }
+
+    private String getType(FlowNode fe) {
+        String t = Karajan.demangle(fe.getTextualName());
+        String nt = NAME_MAPPINGS.get(t);
+        if (nt == null) {
+            return t;
+        }
+        else {
+            return nt;
+        }
+    }
+
+    private String findLine(FlowElement fe) {
+        String line;
+        if (fe.hasProperty("_traceline")) {
+            line = (String) fe.getProperty("_traceline");
+        }
+        else if (fe.hasProperty("_defline")) {
+            line = (String) fe.getProperty("_defline");
+        }
+        else {
+            line = null;
+        }
+        if (line == null || line.equals("-1") || line.equals("")) {
+            return null;
+        }
+        else {
+            return line;
+        }
+    }
+
+    public boolean isEnabled() {
+        return enabled;
+    }
+    
+    public void trace(VariableStack stack, Object msg) throws VariableNotFoundException {
+        trace(ThreadingContext.get(stack).toString(), msg);
+    }
+    
+    public void trace(String thread, Object msg) {
+        String str = source + ", thread " + thread + ", " + msg;
+        logger.info(str);
+        System.out.println(str);
+    }
+    
+    public void trace(String thread, String name, String line, Object msg) {
+        if (line == null) {
+            return;
+        }
+        String str = name + ", line " + line + ", thread " + thread + ", "+ msg;
+        logger.info(str);
+        System.out.println(str);
+    }
+    
+    public void trace(String thread, String line, Object msg) {
+        if (line == null) {
+            return;
+        }
+        String str = source + ", line " + line + ", thread " + thread + ", " + msg;
+        logger.info(str);
+        System.out.println(str);
+    }
+    
+    public void trace(String thread) {
+        logger.info(source + ", thread " + thread);
+        System.out.println(source + ", thread " + thread);
+    }
+    
+    private static Tracer disabledTracer, enabledTracer;
+    
+    public static Tracer getTracer(FlowNode fe) {
+        return getTracer(fe, null);
+    }
+    
+    public static Tracer getTracer(FlowNode fe, String name) {
+        if (globalTracingEnabled) {
+            return new Tracer(fe, name);
+        }
+        else {
+            return getGenericTracer(false);
+        }
+    }
+    
+    public static Tracer getTracer(String line, String name) {
+        if (globalTracingEnabled) {
+            return new Tracer(line, name);
+        }
+        else {
+            return getGenericTracer(false);
+        }
+    }
+    
+    public static Tracer getTracer(String name) {
+        if (globalTracingEnabled) {
+            return new Tracer(name);
+        }
+        else {
+            return getGenericTracer(false);
+        }
+    }
+    
+    public static Tracer getTracer() {
+        return getGenericTracer(globalTracingEnabled);
+    }
+
+    private synchronized static Tracer getGenericTracer(boolean enabled) {
+        if (enabled) {
+            if (enabledTracer == null) {
+                enabledTracer = new Tracer(true);
+            }
+            return enabledTracer;
+        }
+        else {
+            if (disabledTracer == null) {
+                disabledTracer = new Tracer(false);
+            }
+            return disabledTracer;
+        }
+    }
+    
+    public static String getVarName(DSHandle var) {
+        if (var instanceof AbstractDataNode) {
+            AbstractDataNode data = (AbstractDataNode) var;
+            Path path = data.getPathFromRoot();
+            String p;
+            if (path.isEmpty()) {
+                p = "";
+            }
+            else if (path.isArrayIndex(0)) {
+                p = path.toString();
+            }
+            else {
+                p = "." + path.toString();
+            }
+            return data.getDisplayableName() + p;
+        }
+        else {
+            return String.valueOf(var);
+        }
+    }
+    
+    public static String getFutureName(Future future) {
+        if (future instanceof FutureWrapper) {
+            return getVarName(((FutureWrapper) future).getHandle());
+        }
+        else {
+            return future.toString();
+        }
+    }
+    
+    public static Object unwrapHandle(Object o) {
+        if (o instanceof DSHandle) {
+            DSHandle h = (DSHandle) o;
+            if (h.isClosed()) {
+                if (h.getType().isPrimitive()) {
+                    if (Types.STRING.equals(h.getType())) {
+                        return "\"" + h.getValue() + '"';
+                    }
+                    else {
+                        return h.getValue();
+                    }
+                }
+                else if (h.getType().isComposite()){
+                    return getVarName(h);
+                }
+                else {
+                    Mapper m = h.getMapper();
+                    return "<" + m.map(h.getPathFromRoot()) + ">";
+                }
+            }
+            else {
+                return "?" + getVarName(h);
+            }
+        }
+        else {
+            return o;
+        }
+    }
+
+    public static Object fileName(AbstractDataNode n) {
+        if (Types.STRING.equals(n.getType())) {
+            return unwrapHandle(n);
+        }
+        else {
+            Mapper m = n.getActualMapper();
+            if (m == null) {
+                return "?" + getVarName(n);
+            }
+            else {
+                return "<" + m.map(n.getPathFromRoot()) + ">";
+            }
+        }
+    }
+}

Modified: trunk/src/org/griphyn/vdl/karajan/lib/UnitStart.java
===================================================================
--- trunk/src/org/griphyn/vdl/karajan/lib/UnitStart.java	2012-11-10 05:42:36 UTC (rev 6022)
+++ trunk/src/org/griphyn/vdl/karajan/lib/UnitStart.java	2012-11-10 05:43:55 UTC (rev 6023)
@@ -9,6 +9,8 @@
  */
 package org.griphyn.vdl.karajan.lib;
 
+import java.util.ArrayList;
+import java.util.Arrays;
 import java.util.Collections;
 import java.util.LinkedList;
 import java.util.List;
@@ -20,6 +22,7 @@
 import org.globus.cog.karajan.util.ThreadingContext;
 import org.globus.cog.karajan.workflow.ExecutionException;
 import org.globus.cog.karajan.workflow.nodes.FlowNode;
+import org.griphyn.vdl.engine.Karajan;
 import org.griphyn.vdl.karajan.WaitingThreadsMonitor;
 import org.griphyn.vdl.mapping.DSHandle;
 
@@ -33,7 +36,44 @@
     public static final Arg.Optional LINE = new Arg.Optional("line", null);
     public static final Arg.Optional OUTPUTS = new Arg.Optional("outputs", null);
     
+    private Tracer tracer;
+    private List<String> inputArgs, outputArgs;
+    
     @Override
+    protected void initializeStatic() {
+        super.initializeStatic();
+        String type = (String) TYPE.getStatic(this);
+        if (type.equals("PROCEDURE")) {
+            tracer = Tracer.getTracer((FlowNode) getParent(), "APPCALL");
+        }
+        else if (type.equals("COMPOUND")) {
+            tracer = Tracer.getTracer((FlowNode) getParent(), "CALL");
+        }
+        if (tracer != null && tracer.isEnabled()) {
+            populateArgNames();
+        }
+    }
+
+    private void populateArgNames() {
+        String outs = (String) getStaticArguments().get("outputs");
+        if (outs != null && outs.length() > 0) {
+            outputArgs = Arrays.asList(outs.split(","));
+        }
+        else {
+            outputArgs = Collections.emptyList();
+        }
+        String args = (String) getParent().getStaticArguments().get("arguments");
+        if (args != null && args.length() > 0) {
+            inputArgs = new ArrayList<String>(Arrays.asList(args.split(",")));
+            inputArgs.removeAll(outputArgs);
+        }
+        else {
+            inputArgs = Collections.emptyList();
+        }
+        
+    }
+
+    @Override
     public void execute(VariableStack stack) throws ExecutionException {
         executeSimple(stack);
         complete(stack);
@@ -51,6 +91,10 @@
         String name = (String) NAME.getStatic(this);
         String line = (String) LINE.getStatic(this);
         
+        if (tracer != null && tracer.isEnabled()) {
+            tracer.trace(thread.toString(), Karajan.demangle(name) + "(" + formatArguments(stack) + ")");
+        }
+        
         log(true, type, thread, name, line);
         
         String outputs = (String) OUTPUTS.getStatic(this);
@@ -59,6 +103,23 @@
         }
     }
     
+    private String formatArguments(VariableStack stack) {
+        StringBuilder sb = new StringBuilder();
+        boolean first = true;
+        for (String name : inputArgs) {
+            if (first) {
+                first = false;
+            }
+            else {
+                sb.append(", ");
+            }
+            sb.append(Karajan.demangle(name));
+            sb.append(" = ");
+            sb.append(Tracer.unwrapHandle(stack.parentFrame().getVar(name)));
+        }
+        return sb.toString();
+    }
+
     private static final List<DSHandle> EMPTY_OUTPUTS = Collections.emptyList();
 
     private void trackOutputs(VariableStack stack, String outputs, boolean deep) {

Modified: trunk/src/org/griphyn/vdl/karajan/lib/swiftscript/ReadData.java
===================================================================
--- trunk/src/org/griphyn/vdl/karajan/lib/swiftscript/ReadData.java	2012-11-10 05:42:36 UTC (rev 6022)
+++ trunk/src/org/griphyn/vdl/karajan/lib/swiftscript/ReadData.java	2012-11-10 05:43:55 UTC (rev 6023)
@@ -32,6 +32,7 @@
 import org.globus.cog.karajan.arguments.Arg;
 import org.globus.cog.karajan.stack.VariableStack;
 import org.globus.cog.karajan.workflow.ExecutionException;
+import org.griphyn.vdl.karajan.lib.Tracer;
 import org.griphyn.vdl.karajan.lib.VDLFunction;
 import org.griphyn.vdl.mapping.AbsFile;
 import org.griphyn.vdl.mapping.AbstractDataNode;
@@ -48,14 +49,25 @@
 	public static final Arg DEST = new Arg.Positional("dest");
 	public static final Arg SRC = new Arg.Positional("src");
 	public static boolean warning;
+	
+	public static Tracer tracer;
 
 	static {
 		setArguments(ReadData.class, new Arg[] { DEST, SRC });
 	}
+	
+	@Override
+    protected void initializeStatic() {
+        super.initializeStatic();
+        tracer = Tracer.getTracer(this);
+    }
 
-	protected Object function(VariableStack stack) throws ExecutionException {
+    protected Object function(VariableStack stack) throws ExecutionException {
 		DSHandle dest = (DSHandle) DEST.getValue(stack);
 		AbstractDataNode src = (AbstractDataNode) SRC.getValue(stack);
+		if (tracer.isEnabled()) {
+		    tracer.trace(stack, Tracer.fileName(src));
+		}
 		src.waitFor();
 		if (src.getType().equals(Types.STRING)) {
 			readData(dest, (String) src.getValue());
@@ -175,8 +187,8 @@
 		}
 		else {
 			String[] header = line.split("\\s+");
-			Set t = new HashSet(type.getFieldNames());
-			Set h = new HashSet(Arrays.asList(header));
+			Set<String> t = new HashSet<String>(type.getFieldNames());
+			Set<String> h = new HashSet<String>(Arrays.asList(header));
 			if (t.size() != h.size()) {
 				throw new ExecutionException("File header does not match type. " + "Expected "
 						+ t.size() + " whitespace separated items. Got " + h.size() + " instead.");

Modified: trunk/src/org/griphyn/vdl/mapping/MappingParamSet.java
===================================================================
--- trunk/src/org/griphyn/vdl/mapping/MappingParamSet.java	2012-11-10 05:42:36 UTC (rev 6022)
+++ trunk/src/org/griphyn/vdl/mapping/MappingParamSet.java	2012-11-10 05:43:55 UTC (rev 6023)
@@ -29,6 +29,10 @@
     public Object get(MappingParam p) {
         return params.get(p.getName());
     }
+    
+    public Object _get(String name) {
+        return params.get(name);
+    }
 
     public boolean isPresent(MappingParam p) {
         return params.containsKey(p.getName());

Modified: trunk/src/org/griphyn/vdl/mapping/RootArrayDataNode.java
===================================================================
--- trunk/src/org/griphyn/vdl/mapping/RootArrayDataNode.java	2012-11-10 05:42:36 UTC (rev 6022)
+++ trunk/src/org/griphyn/vdl/mapping/RootArrayDataNode.java	2012-11-10 05:43:55 UTC (rev 6023)
@@ -17,16 +17,15 @@
 
 package org.griphyn.vdl.mapping;
 
-import java.util.Map;
+import org.apache.log4j.Logger;
+import org.globus.cog.karajan.stack.VariableStack;
+import org.globus.cog.karajan.workflow.futures.Future;
+import org.globus.cog.karajan.workflow.futures.FutureListener;
+import org.globus.cog.karajan.workflow.futures.FutureNotYetAvailable;
+import org.griphyn.vdl.karajan.lib.Tracer;
+import org.griphyn.vdl.type.Field;
+import org.griphyn.vdl.type.Type;
 
-import org.apache.log4j.Logger;
-import org.globus.cog.karajan.stack.VariableStack;
-import org.globus.cog.karajan.workflow.futures.Future;
-import org.globus.cog.karajan.workflow.futures.FutureListener;
-import org.globus.cog.karajan.workflow.futures.FutureNotYetAvailable;
-import org.griphyn.vdl.type.Field;
-import org.griphyn.vdl.type.Type;
-
 public class RootArrayDataNode extends ArrayDataNode implements FutureListener {
 
     Logger logger = Logger.getLogger(RootArrayDataNode.class);
@@ -34,7 +33,9 @@
 	private boolean initialized = false;
 	private Mapper mapper;
 	private MappingParamSet params;
-	private AbstractDataNode waitingMapperParam;
+	private AbstractDataNode waitingMapperParam;
+	
+	private static final Tracer tracer = Tracer.getTracer("VARIABLE");
 
 	/**
 	 * Instantiate a root array data node with specified type.
@@ -61,6 +62,10 @@
 		waitingMapperParam = params.getFirstOpenParamValue();
         if (waitingMapperParam != null) {
             waitingMapperParam.getFutureWrapper().addModificationAction(this, null);
+            if (tracer.isEnabled()) {
+                tracer.trace(getThread(), getDeclarationLine(), getDisplayableName() + " wait " 
+                    + Tracer.getVarName(waitingMapperParam));
+            }
             return;
         }
 	    
@@ -93,7 +98,11 @@
 		}
 	}
 	
-	public void futureModified(Future f, VariableStack stack) {
+	public void futureModified(Future f, VariableStack stack) {
+	    if (tracer.isEnabled()) {
+	        tracer.trace(getThread(), getDeclarationLine(), getDisplayableName() + " available " 
+                    + Tracer.getFutureName(f));
+	    }
 	    innerInit();
     }
 
@@ -139,6 +148,9 @@
 
     private synchronized void initialized() {
         initialized = true;
-        waitingMapperParam = null;
+        waitingMapperParam = null;
+        if (tracer.isEnabled()) {
+            tracer.trace(getThread(), getDeclarationLine(), getDisplayableName() + " initialized");
+        }
     }
 }

Modified: trunk/src/org/griphyn/vdl/mapping/RootDataNode.java
===================================================================
--- trunk/src/org/griphyn/vdl/mapping/RootDataNode.java	2012-11-10 05:42:36 UTC (rev 6022)
+++ trunk/src/org/griphyn/vdl/mapping/RootDataNode.java	2012-11-10 05:43:55 UTC (rev 6023)
@@ -25,6 +25,8 @@
 import org.globus.cog.karajan.workflow.futures.Future;
 import org.globus.cog.karajan.workflow.futures.FutureListener;
 import org.globus.cog.karajan.workflow.futures.FutureNotYetAvailable;
+import org.griphyn.vdl.karajan.lib.Tracer;
+import org.griphyn.vdl.karajan.lib.VDLFunction;
 import org.griphyn.vdl.type.Field;
 import org.griphyn.vdl.type.Type;
 
@@ -36,6 +38,8 @@
 	private Mapper mapper;
 	private MappingParamSet params;
 	private AbstractDataNode waitingMapperParam;
+	
+	private static final Tracer tracer = Tracer.getTracer("VARIABLE");
 
 	public RootDataNode(Type type) {
 		super(Field.Factory.createField(null, type));
@@ -62,6 +66,10 @@
 	    waitingMapperParam = params.getFirstOpenParamValue();
 	    if (waitingMapperParam != null) {
             waitingMapperParam.getFutureWrapper().addModificationAction(this, null);
+            if (tracer.isEnabled()) {
+                tracer.trace(getThread(), getDeclarationLine(), getDisplayableName() + " wait " 
+                    + Tracer.getVarName(waitingMapperParam));
+            }
             return;
 	    }
 	    
@@ -101,6 +109,10 @@
 	}
 
 	public void futureModified(Future f, VariableStack stack) {
+	    if (tracer.isEnabled()) {
+            tracer.trace(getThread(), getDeclarationLine(), getDisplayableName() + " available " 
+                    + Tracer.getFutureName(f));
+        }
 		innerInit();
 	}
 
@@ -238,5 +250,8 @@
 	private synchronized void initialized() {
 		initialized = true;
 		waitingMapperParam = null;
+		if (tracer.isEnabled()) {
+            tracer.trace(getThread(), getDeclarationLine(), getDisplayableName() + " initialized");
+        }
 	}
 }

Modified: trunk/src/org/griphyn/vdl/util/VDL2Config.java
===================================================================
--- trunk/src/org/griphyn/vdl/util/VDL2Config.java	2012-11-10 05:42:36 UTC (rev 6022)
+++ trunk/src/org/griphyn/vdl/util/VDL2Config.java	2012-11-10 05:43:55 UTC (rev 6023)
@@ -231,10 +231,19 @@
 	public boolean getSitedirKeep() {
 		return Boolean.valueOf(getProperty(VDL2ConfigProperties.SITEDIR_KEEP, "true")).booleanValue();
 	}
+	
+	private Boolean provenanceLogCached;
 
 	public boolean getProvenanceLog() {
-		return Boolean.valueOf(getProperty(VDL2ConfigProperties.PROVENANCE_LOG, "false")).booleanValue();
+	    if (provenanceLogCached == null) {
+	        provenanceLogCached = Boolean.valueOf(getProperty(VDL2ConfigProperties.PROVENANCE_LOG, "false"));
+	    }
+		return provenanceLogCached;
 	}
+	
+	public boolean isTracingEnabled() {
+        return Boolean.valueOf(getProperty(VDL2ConfigProperties.TRACING_ENABLED, "false")).booleanValue();
+    }
 
 	public String getTickerDateFormat() { 
 		return getProperty("ticker.date.format");

Modified: trunk/src/org/griphyn/vdl/util/VDL2ConfigProperties.java
===================================================================
--- trunk/src/org/griphyn/vdl/util/VDL2ConfigProperties.java	2012-11-10 05:42:36 UTC (rev 6022)
+++ trunk/src/org/griphyn/vdl/util/VDL2ConfigProperties.java	2012-11-10 05:43:55 UTC (rev 6023)
@@ -43,6 +43,7 @@
 	public static final String SITEDIR_KEEP = "sitedir.keep";
 	public static final String PROVENANCE_LOG = "provenance.log";
 	public static final String FILE_GC_ENABLED = "file.gc.enabled";
+	public static final String TRACING_ENABLED = "tracing.enabled";
 	public static final Map<String, PropInfo> PROPERTIES;
 
 	static {
@@ -137,6 +138,11 @@
 		PROPERTIES.put(FILE_GC_ENABLED, new PropInfo("<true|false>", "Allows disabling the file garbage collector. " +
 				"If set to false, files mapped by collectable mappers (such as the concurrent mapper) will not be " +
 				"deleted when their swift variables go out of scope."));
+		
+		PROPERTIES.put(TRACING_ENABLED, new PropInfo("<true|false>", "Enables execution tracing. If set to 'true', " +
+				"operations within swift such as iterations, invocations, assignments, and declarations, as well " +
+				"as data dependencies will be logged. This comes at a cost in performance. It is therefore " +
+				"disabled by default."));
 	}
 
 	public static Map<String, PropInfo> getPropertyDescriptions() {




More information about the Swift-commit mailing list