small improvements to timing logging

mp2079 [2003-05-05 17:06:39]
small improvements to timing logging
Filename
littlejil/LittleJILExpanderPlugin.java
littlejil/PluginUtil.java
littlejil/TaskExecutorInternalPlugin.java
littlejil/TaskExpanderPlugin.java
littlejil/log4j.properties
diff --git a/littlejil/LittleJILExpanderPlugin.java b/littlejil/LittleJILExpanderPlugin.java
index fd27002..f34fcf2 100644
--- a/littlejil/LittleJILExpanderPlugin.java
+++ b/littlejil/LittleJILExpanderPlugin.java
@@ -114,16 +114,16 @@ public class LittleJILExpanderPlugin extends ComponentPlugin {
             stepsTable = (LittleJILStepsTable) stepsTableSubscription.first();
         }

-        //resourceTable = (LittleJILResourceTable) resourceTableSubscription.first();
-        //assert(resourceTable != null);
+        resourceTable = (LittleJILResourceTable) resourceTableSubscription.first();
+        assert(resourceTable != null);

-        // TODO: temporary
+        /*// TODO: temporary
         if (resourceTableSubscription.size() == 0) {
             resourceTable = new LittleJILResourceTable();
             blackboard.publishAdd(resourceTable);
         } else {
             resourceTable = (LittleJILResourceTable) resourceTableSubscription.first();
-        }
+        }*/

         // process any diagrams found
         for (Enumeration e = diagramSubscription.getAddedList(); e.hasMoreElements();) {
@@ -157,6 +157,8 @@ public class LittleJILExpanderPlugin extends ComponentPlugin {
             blackboard.publishAdd(rootTask);
             blackboard.publishAdd(factory.createExpansion(rootTask.getPlan(), rootTask, workflow, null));

+            PluginUtil.Timing.addTimestamp("publish rootTask");
+
         }

         // process any HandlerBindings that may have been posted by the ExceptionHandlerPlugin
diff --git a/littlejil/PluginUtil.java b/littlejil/PluginUtil.java
index 52dc79a..c3511ff 100644
--- a/littlejil/PluginUtil.java
+++ b/littlejil/PluginUtil.java
@@ -36,7 +36,7 @@ public class PluginUtil {
      */
     public static class Timing {

-        private static final Logger logger = Logger.getLogger("Timing");
+        private static final Logger logger = Logger.getLogger(Timing.class);

         private static ArrayList columns = new ArrayList();
         private static StringBuffer row = new StringBuffer();
@@ -44,7 +44,6 @@ public class PluginUtil {
         private static boolean printColumns = false;

         public static void addTimestamp(String name) {
-
             addTimestamp(name, System.currentTimeMillis());
         }

@@ -57,9 +56,16 @@ public class PluginUtil {
             if (columns.size() == currentCol) {
                 columns.add(name);
                 printColumns = true;
-            }
-            else if (!columns.get(currentCol).equals(name)) {
-                columns.add(currentCol, name);
+            } else if (!columns.get(currentCol).equals(name)) {
+
+                // if the name matches the next column, then assume the current column
+                // is no longer used, and remove it
+                if (columns.size() > currentCol + 1 && columns.get(currentCol + 1).equals(name)) {
+                    columns.remove(currentCol);
+                } else {
+                    // otherwise, we assume this is a new column and add it
+                    columns.add(currentCol, name);
+                }
                 printColumns = true;
             }

@@ -74,7 +80,12 @@ public class PluginUtil {

         public static void newRow() {

+            if (row.length() == 0) {
+                return; // nothing to print
+            }
+
             if (printColumns) {
+                logger.debug("");
                 StringBuffer buf = new StringBuffer();
                 for (int i = 0; i < columns.size(); i++) {
                     String s = (String) columns.get(i);
@@ -93,5 +104,35 @@ public class PluginUtil {
             currentCol = 0;
         }

+        // for testing only
+        public static void main(String[] args) {
+            addTimestamp("foo");
+            addTimestamp("bar");
+            newRow();
+
+            addTimestamp("foo");
+            addTimestamp("bar");
+            newRow();
+
+            addTimestamp("foo");
+            addTimestamp("glob");
+            addTimestamp("bar");
+            newRow();
+
+            addTimestamp("foo");
+            addTimestamp("glob");
+            addTimestamp("bar");
+            newRow();
+
+            addTimestamp("foo");
+            addTimestamp("bar");
+            newRow();
+
+            addTimestamp("glob");
+            addTimestamp("foo");
+            addTimestamp("bar");
+            newRow();
+        }
+
     }
 }
diff --git a/littlejil/TaskExecutorInternalPlugin.java b/littlejil/TaskExecutorInternalPlugin.java
index 80a556c..8c45463 100644
--- a/littlejil/TaskExecutorInternalPlugin.java
+++ b/littlejil/TaskExecutorInternalPlugin.java
@@ -69,7 +69,11 @@ public class TaskExecutorInternalPlugin extends AbstractTaskExecutorPlugin {
                 }

                 Hashtable outParams = new Hashtable();
-                executable.execute(task.getVerb().toString(), inParams, outParams);
+
+                String name = task.getVerb().toString();
+                PluginUtil.Timing.addTimestamp("exec " + name);
+                executable.execute(name, inParams, outParams);
+                PluginUtil.Timing.addTimestamp("exec " + name);

                 // task executed successfully
                 logger.debug("executable for task " + task.getVerb() + " executed successfully");
diff --git a/littlejil/TaskExpanderPlugin.java b/littlejil/TaskExpanderPlugin.java
index a61edeb..f0e955f 100644
--- a/littlejil/TaskExpanderPlugin.java
+++ b/littlejil/TaskExpanderPlugin.java
@@ -160,36 +160,8 @@ public class TaskExpanderPlugin extends ComponentPlugin {
                         logger.debug("task " + constrainedTask.getVerb() + " has more constraints");
                         continue;
                     }
-                    // if this task is a CHOICE task, choose one of the substeps and ask the
-                    // LittleJILExpanderPlugin to expand it
-                    else if (constrainedTask.getAnnotation() != null && constrainedTask.getAnnotation() instanceof ChoiceAnnotation) {
-
-                        logger.debug("task " + constrainedTask.getVerb() + " is a CHOICE task");
-                        Step step = ((ChoiceAnnotation) constrainedTask.getAnnotation()).chooseSubstep();
-
-                        MakeTaskRequest request = new MakeTaskRequest(constrainedTask, step);
-                        blackboard.publishAdd(request);
-                    } else {
-                        logger.info("publishing task " + constrainedTask.getVerb());
-                        setInParams(constrainedTask);
-                        blackboard.publishAdd(constrainedTask);
-
-                        PlanElement planElement = constrainedTask.getPlanElement();
-                        if (planElement != null && planElement instanceof Expansion) {
-                            //logger.debug("publishing tasks's expansion:" + planElement);
-                            blackboard.publishChange(planElement);
-
-                            // notify listeners of task being published
-                            for (Iterator iterator = listeners.iterator(); iterator.hasNext();) {
-                                Listener listener = (Listener) iterator.next();
-                                listener.taskPublished(constrainedTask.getVerb().toString());
-                            }
-                        } else {
-                            for (Iterator iterator = listeners.iterator(); iterator.hasNext();) {
-                                Listener listener = (Listener) iterator.next();
-                                listener.leafTaskPublished(constrainedTask.getVerb().toString());
-                            }
-                        }
+                    else {
+                        publishTask(constrainedTask);
                     }
                 }
             }
@@ -248,42 +220,49 @@ public class TaskExpanderPlugin extends ComponentPlugin {
                 }

                 if (!constrained) {
+                    publishTask(task);
+                }

-                    // if this a task is a CHOICE task, choose one of the substeps and ask the
-                    // LittleJILExpanderPlugin to expand it
-                    if (task.getAnnotation() != null && task.getAnnotation() instanceof ChoiceAnnotation) {

-                        logger.debug("task " + task.getVerb() + " is a CHOICE task");
-                        Step step = ((ChoiceAnnotation) task.getAnnotation()).chooseSubstep();
+            }
+        }
+    }

-                        MakeTaskRequest request = new MakeTaskRequest(task, step);
-                        blackboard.publishAdd(request);
-                    } else {
-                        logger.debug("task " + task.getVerb() + " is not constrained, publishing it");
+    private void publishTask(Task task) {

-                        setInParams(task);
-                        blackboard.publishAdd(task);
+        // if this a task is a CHOICE task, choose one of the substeps and ask the
+        // LittleJILExpanderPlugin to expand it
+        if (task.getAnnotation() != null && task.getAnnotation() instanceof ChoiceAnnotation) {

-                        PlanElement planElement = task.getPlanElement();
-                        if (planElement != null && planElement instanceof Expansion) {
-                            //logger.debug("publishing tasks's expansion:" + planElement);
-                            blackboard.publishChange(planElement);
+            logger.debug("task " + task.getVerb() + " is a CHOICE task");
+            Step step = ((ChoiceAnnotation) task.getAnnotation()).chooseSubstep();

-                            // notify listeners of task being published
-                            for (Iterator iterator = listeners.iterator(); iterator.hasNext();) {
-                                Listener listener = (Listener) iterator.next();
-                                listener.taskPublished(task.getVerb().toString());
-                            }
-                        } else {
-                            for (Iterator iterator = listeners.iterator(); iterator.hasNext();) {
-                                Listener listener = (Listener) iterator.next();
-                                listener.leafTaskPublished(task.getVerb().toString());
-                            }
-                        }
-                    }
-                }
+            MakeTaskRequest request = new MakeTaskRequest(task, step);
+            blackboard.publishAdd(request);
+
+        } else {
+            logger.debug("task " + task.getVerb() + " is not constrained, publishing it");
+
+            setInParams(task);
+            blackboard.publishAdd(task);

+            PlanElement planElement = task.getPlanElement();
+            if (planElement != null && planElement instanceof Expansion) {
+                //logger.debug("publishing tasks's expansion:" + planElement);
+                blackboard.publishChange(planElement);
+
+                // notify listeners of task being published
+                for (Iterator iterator = listeners.iterator(); iterator.hasNext();) {
+                    Listener listener = (Listener) iterator.next();
+                    listener.taskPublished(task.getVerb().toString());
+                }
+            } else {

+                // notify listeners of task being published
+                for (Iterator iterator = listeners.iterator(); iterator.hasNext();) {
+                    Listener listener = (Listener) iterator.next();
+                    listener.leafTaskPublished(task.getVerb().toString());
+                }
             }
         }
     }
diff --git a/littlejil/log4j.properties b/littlejil/log4j.properties
index 71beb02..30f8dd1 100644
--- a/littlejil/log4j.properties
+++ b/littlejil/log4j.properties
@@ -1,17 +1,17 @@
-log4j.rootLogger=DEBUG, Console
+log4j.rootLogger=WARN, Console

-log4j.logger.org.cougaar=WARN
 log4j.logger.psl.workflakes.littlejil=INFO
 log4j.logger.psl.ai2tv=DEBUG

-log4j.logger.Timing=DEBUG,Timing
+log4j.logger.psl.workflakes.littlejil.PluginUtil$Timing=DEBUG,Timing
+log4j.additivity.psl.workflakes.littlejil.PluginUtil$Timing=false

 log4j.appender.Console=org.apache.log4j.ConsoleAppender
 log4j.appender.Console.layout=org.apache.log4j.PatternLayout
 log4j.appender.Console.layout.ConversionPattern=%d{mm:ss} %C{1}: %m%n

 log4j.appender.Timing=org.apache.log4j.FileAppender
-log4j.appender.Timing.file=ai2tv-timing.log
+log4j.appender.Timing.file=ai2tv-timing.csv
 log4j.appender.Timing.layout=org.apache.log4j.PatternLayout
 log4j.appender.Timing.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss.SSS},%m%n