Watcher: Replace System.currentTimeMillis() with nanotime() (elastic/x-pack-elasticsearch#2393)

Enjoy the luxury of monotonically increasing clocks. So that
the duration will never be zero.

Original commit: elastic/x-pack-elasticsearch@c934ff0adb

plugin/src/main/java/org/elasticsearch/xpack/watcher/execution/ExecutionService.java

@@ -56,6 +56,7 @@ import java.util.HashMap;
 import java.util.LinkedList;
 import java.util.List;
 import java.util.Map;
+import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
 
 import static org.joda.time.DateTimeZone.UTC;
@@ -460,9 +461,9 @@ public class ExecutionService extends AbstractComponent {
             // actions
             ctx.beforeActions();
             for (ActionWrapper action : watch.actions()) {
-                long now = System.currentTimeMillis();
+                long start = System.nanoTime();
                 ActionWrapper.Result actionResult = action.execute(ctx);
-                long executionTime = System.currentTimeMillis() - now;
+                long executionTime = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - start);
                 String type = action.action().type();
                 actionByTypeExecutionTime.putIfAbsent(type, new MeanMetric());
                 actionByTypeExecutionTime.get(type).inc(executionTime);

plugin/src/main/java/org/elasticsearch/xpack/watcher/execution/WatchExecutionContext.java

@@ -22,6 +22,7 @@ import java.util.Collections;
 import java.util.HashMap;
 import java.util.Map;
 import java.util.concurrent.ConcurrentMap;
+import java.util.concurrent.TimeUnit;
 
 public abstract class WatchExecutionContext {
 
@@ -31,7 +32,7 @@ public abstract class WatchExecutionContext {
     private final TimeValue defaultThrottlePeriod;
 
     private ExecutionPhase phase = ExecutionPhase.AWAITS_EXECUTION;
-    private long startTimestamp;
+    private long relativeStartTime;
     private Watch watch;
 
     private Payload payload;
@@ -133,7 +134,7 @@ public abstract class WatchExecutionContext {
 
     public void start() {
         assert phase == ExecutionPhase.AWAITS_EXECUTION;
-        startTimestamp = System.currentTimeMillis();
+        relativeStartTime = System.nanoTime();
         phase = ExecutionPhase.STARTED;
     }
 
@@ -210,24 +211,24 @@ public abstract class WatchExecutionContext {
     public WatchRecord abortFailedExecution(String message) {
         assert !phase.sealed();
         phase = ExecutionPhase.ABORTED;
-        long executionFinishMs = System.currentTimeMillis();
-        WatchExecutionResult result = new WatchExecutionResult(this, executionFinishMs - startTimestamp);
+        long executionTime = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - relativeStartTime);
+        WatchExecutionResult result = new WatchExecutionResult(this, executionTime);
         return new WatchRecord.MessageWatchRecord(this, result, message);
     }
 
     public WatchRecord abortFailedExecution(Exception e) {
         assert !phase.sealed();
         phase = ExecutionPhase.ABORTED;
-        long executionFinishMs = System.currentTimeMillis();
-        WatchExecutionResult result = new WatchExecutionResult(this, executionFinishMs - startTimestamp);
+        long executionTime = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - relativeStartTime);
+        WatchExecutionResult result = new WatchExecutionResult(this, executionTime);
         return new WatchRecord.ExceptionWatchRecord(this, result, e);
     }
 
     public WatchRecord finish() {
         assert !phase.sealed();
         phase = ExecutionPhase.FINISHED;
-        long executionFinishMs = System.currentTimeMillis();
-        WatchExecutionResult result = new WatchExecutionResult(this, executionFinishMs - startTimestamp);
+        long executionTime = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - relativeStartTime);
+        WatchExecutionResult result = new WatchExecutionResult(this, executionTime);
         return new WatchRecord.MessageWatchRecord(this, result);
     }
 

plugin/src/test/java/org/elasticsearch/xpack/watcher/execution/ExecutionServiceTests.java

@@ -72,7 +72,7 @@ import static java.util.Arrays.asList;
 import static java.util.Collections.singletonMap;
 import static org.elasticsearch.common.unit.TimeValue.timeValueSeconds;
 import static org.elasticsearch.common.xcontent.XContentFactory.jsonBuilder;
-import static org.hamcrest.Matchers.greaterThan;
+import static org.hamcrest.Matchers.greaterThanOrEqualTo;
 import static org.hamcrest.Matchers.hasSize;
 import static org.hamcrest.Matchers.instanceOf;
 import static org.hamcrest.Matchers.is;
@@ -151,7 +151,12 @@ public class ExecutionServiceTests extends ESTestCase {
 
         Condition.Result conditionResult = AlwaysCondition.RESULT_INSTANCE;
         Condition condition = mock(Condition.class);
-        when(condition.execute(any(WatchExecutionContext.class))).thenReturn(conditionResult);
+        // introduce a very short sleep time which we can use to check if the duration in milliseconds is correctly created
+        long randomConditionDurationMs = randomIntBetween(1, 10);
+        when(condition.execute(any(WatchExecutionContext.class))).then(invocationOnMock -> {
+            Thread.sleep(randomConditionDurationMs);
+            return conditionResult;
+        });
 
         // watch level transform
         Transform.Result watchTransformResult = mock(Transform.Result.class);
@@ -222,6 +227,10 @@ public class ExecutionServiceTests extends ESTestCase {
         verify(watchTransform, times(1)).execute(context, payload);
         verify(action, times(1)).execute("_action", context, payload);
 
+        // test execution duration
+        assertThat(watchRecord.result().executionDurationMs(), is(greaterThanOrEqualTo(randomConditionDurationMs)));
+        assertThat(watchRecord.result().executionTime(), is(notNullValue()));
+
         // test stats
         XContentSource source = new XContentSource(jsonBuilder().map(executionService.usageStats()));
         assertThat(source.getValue("execution.actions._all.total_time_in_ms"), is(notNullValue()));

plugin/src/test/resources/rest-api-spec/test/watcher/execute_watch/10_basic.yml

@@ -61,6 +61,7 @@ teardown:
   - match: { watch_record.status.state.active: true }
   - is_true: watch_record.node
   - match: { watch_record.status.actions.indexme.ack.state: "ackable" }
+  - gt: { watch_record.result.execution_duration: 0 }
 
 ---
 "Test execute watch API with user supplied watch":