diff --git a/src/main/java/emissary/core/BaseDataObject.java b/src/main/java/emissary/core/BaseDataObject.java index 58b42ad283..dd740c93f5 100755 --- a/src/main/java/emissary/core/BaseDataObject.java +++ b/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); diff --git a/src/main/java/emissary/core/HDMobileAgent.java b/src/main/java/emissary/core/HDMobileAgent.java index abf326833e..0c090bc330 100755 --- a/src/main/java/emissary/core/HDMobileAgent.java +++ b/src/main/java/emissary/core/HDMobileAgent.java @@ -403,6 +403,7 @@ protected void switchPrimaryPayload(final int i) { */ protected List atPlaceHD(final IServiceProviderPlace place, final List payloadListArg) { MDC.put(MDCConstants.SERVICE_LOCATION, place.toString()); + long timeInPlace; logger.debug("In atPlaceHD {} with {} payload items", place, payloadListArg.size()); List ret = Collections.emptyList(); @@ -417,7 +418,13 @@ protected List 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 it = ret.iterator(); it.hasNext();) { final IBaseDataObject ibdo = it.next(); diff --git a/src/main/java/emissary/core/IBaseDataObject.java b/src/main/java/emissary/core/IBaseDataObject.java index 2e46dfc48b..596a73fdd1 100755 --- a/src/main/java/emissary/core/IBaseDataObject.java +++ b/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 * diff --git a/src/main/java/emissary/core/MobileAgent.java b/src/main/java/emissary/core/MobileAgent.java index f21793408b..ba4af63338 100755 --- a/src/main/java/emissary/core/MobileAgent.java +++ b/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); } diff --git a/src/main/java/emissary/core/TransformHistory.java b/src/main/java/emissary/core/TransformHistory.java index 3b335c5866..455b4be1e6 100644 --- a/src/main/java/emissary/core/TransformHistory.java +++ b/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; } diff --git a/src/main/java/emissary/util/PayloadUtil.java b/src/main/java/emissary/util/PayloadUtil.java index 068a45a6f6..d6904b7b29 100755 --- a/src/main/java/emissary/util/PayloadUtil.java +++ b/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();