1441 - Add Time in Place to Transform History

src/main/java/emissary/core/BaseDataObject.java

@@ -773,6 +773,11 @@ public void appendTransformHistory(final String key, boolean coordinated) {
         this.history.append(key, coordinated);
     }
 
+    @Override
+    public void addTimeInLastPlace(long timeInPlace) {
+        this.history.addTimeInPlace(timeInPlace);
+    }
+
     @Override
     public void setHistory(TransformHistory newHistory) {
         this.history.set(newHistory);

src/main/java/emissary/core/HDMobileAgent.java

@@ -403,6 +403,7 @@ protected void switchPrimaryPayload(final int i) {
      */
     protected List<IBaseDataObject> atPlaceHD(final IServiceProviderPlace place, final List<IBaseDataObject> payloadListArg) {
         MDC.put(MDCConstants.SERVICE_LOCATION, place.toString());
+        long timeInPlace;
         logger.debug("In atPlaceHD {} with {} payload items", place, payloadListArg.size());
 
         List<IBaseDataObject> ret = Collections.emptyList();
@@ -417,7 +418,13 @@ protected List<IBaseDataObject> atPlaceHD(final IServiceProviderPlace place, fin
                 addMoveErrorCount(payloadListArg);
             }
 
+            long startTime = System.nanoTime();
             ret = place.agentProcessHeavyDuty(payloadListArg);
+            long endTime = System.nanoTime();
+            timeInPlace = (endTime - startTime);
+            for (IBaseDataObject payload : payloadListArg) {
+                payload.addTimeInLastPlace(timeInPlace);
+            }
 
             for (Iterator<IBaseDataObject> it = ret.iterator(); it.hasNext();) {
                 final IBaseDataObject ibdo = it.next();

src/main/java/emissary/core/IBaseDataObject.java

@@ -743,6 +743,13 @@ enum MergePolicy {
      */
     void appendTransformHistory(String key, boolean coordinated);
 
+    /**
+     * Adds the given time in place to the last entry in transform history.
+     *
+     * @param timeInPlace the time in place in nanoseconds
+     */
+    void addTimeInLastPlace(long timeInPlace);
+
     /**
      * Return what machine we are located on
      * 

src/main/java/emissary/core/MobileAgent.java

@@ -291,6 +291,7 @@ protected void agentControl(final IServiceProviderPlace currentPlaceArg) {
                 recordHistory(newEntry, this.payload);
             }
 
+
             // A local place, around the loop and hit it
             if (newEntry.isLocal()) {
                 logger.debug("Choosing local place {}", newEntry.getFullKey());
@@ -338,6 +339,7 @@ protected void agentControl(final IServiceProviderPlace currentPlaceArg) {
      * @param payloadArg the data for the place to operate on
      */
     protected void atPlace(final IServiceProviderPlace place, final IBaseDataObject payloadArg) {
+        long timeInPlace;
         logger.debug("In atPlace {} with {}", place, payloadArg.shortName());
 
         try (TimedResource timer = resourceWatcherStart(place)) {
@@ -348,7 +350,11 @@ protected void atPlace(final IServiceProviderPlace place, final IBaseDataObject
                 payloadArg.setParameter("AGENT_MOVE_ERRORS", Integer.toString(this.moveErrorsOccurred));
             }
 
+            long startTime = System.nanoTime();
             place.agentProcessCall(payloadArg);
+            long endTime = System.nanoTime();
+            timeInPlace = (endTime - startTime);
+            payloadArg.addTimeInLastPlace(timeInPlace);
 
             if (this.moveErrorsOccurred > 0) {
                 payloadArg.deleteParameter("AGENT_MOVE_ERRORS");
@@ -778,6 +784,7 @@ protected void logAgentCompletion(final IBaseDataObject payloadArg) {
      * @param place where the processing is taking place
      * @param payloadArg the dataobject that is being processed
      */
+
     protected void recordHistory(final IServiceProviderPlace place, final IBaseDataObject payloadArg) {
         recordHistory(place.getDirectoryEntry(), payloadArg);
     }

src/main/java/emissary/core/TransformHistory.java

@@ -167,6 +167,13 @@ public boolean beforeStart() {
         return s.contains(IServiceProviderPlace.SPROUT_KEY);
     }
 
+    public void addTimeInPlace(long timeInPlace) {
+        if (history.isEmpty()) {
+            return;
+        }
+        history.get(history.size() - 1).setTimeInPlace(timeInPlace);
+    }
+
     @Override
     public String toString() {
         final StringBuilder myOutput = new StringBuilder();
@@ -179,6 +186,7 @@ public String toString() {
     public static class History {
         String key;
         boolean coordinated;
+        long timeInPlace;
 
         /**
          * Needed to support Kryo deserialization
@@ -194,6 +202,10 @@ public History(String key, boolean coordinated) {
             this.coordinated = coordinated;
         }
 
+        public void setTimeInPlace(long timeInPlace) {
+            this.timeInPlace = timeInPlace;
+        }
+
         public String getKey() {
             return key;
         }
@@ -202,6 +214,10 @@ public String getKeyNoUrl() {
             return StringUtils.substringBefore(key, ".http");
         }
 
+        public double getTimeInPlace() {
+            return timeInPlace;
+        }
+
         public boolean wasCoordinated() {
             return coordinated;
         }

src/main/java/emissary/util/PayloadUtil.java

@@ -131,12 +131,15 @@ public static String getPayloadDisplayString(final IBaseDataObject payload) {
                     .append("\n");
         } else {
             for (final TransformHistory.History h : th) {
+                double msInPlace = h.getTimeInPlace() / 1_000_000;
                 sb.append(" ");
                 if (h.wasCoordinated()) {
                     sb.append(" ");
                 }
                 // check is NO_URL or not
-                sb.append("    ").append(historyCase.equals(NO_URL) ? h.getKeyNoUrl() : h.getKey()).append("\n");
+                sb.append("    ").append(historyCase.equals(NO_URL) ? h.getKeyNoUrl() : h.getKey()).append(" Time: ")
+                        .append(msInPlace).append("ms")
+                        .append("\n");
             }
         }
         return sb.toString();