Report image pull duration metric

2 files changed, 42 insertions, 7 deletions

diff --git a/docker-api/src/main/java/com/yahoo/vespa/hosted/dockerapi/DockerEngine.java b/docker-api/src/main/java/com/yahoo/vespa/hosted/dockerapi/DockerEngine.java
index 7d63c66131d..25b8a1c2747 100644
--- a/docker-api/src/main/java/com/yahoo/vespa/hosted/dockerapi/DockerEngine.java
+++ b/docker-api/src/main/java/com/yahoo/vespa/hosted/dockerapi/DockerEngine.java
@@ -27,10 +27,14 @@ import com.yahoo.vespa.hosted.dockerapi.exception.ContainerNotFoundException;
 import com.yahoo.vespa.hosted.dockerapi.exception.DockerException;
 import com.yahoo.vespa.hosted.dockerapi.exception.DockerExecTimeoutException;
 import com.yahoo.vespa.hosted.dockerapi.metrics.Counter;
+import com.yahoo.vespa.hosted.dockerapi.metrics.Dimensions;
+import com.yahoo.vespa.hosted.dockerapi.metrics.Gauge;
 import com.yahoo.vespa.hosted.dockerapi.metrics.Metrics;
 
 import java.io.ByteArrayOutputStream;
+import java.time.Clock;
 import java.time.Duration;
+import java.time.Instant;
 import java.util.Arrays;
 import java.util.HashSet;
 import java.util.List;
@@ -58,16 +62,20 @@ public class DockerEngine implements ContainerEngine {
 
     private final DockerClient dockerClient;
     private final DockerImageGarbageCollector dockerImageGC;
+    private final Metrics metrics;
     private final Counter numberOfDockerApiFails;
+    private final Clock clock;
 
     @Inject
     public DockerEngine(Metrics metrics) {
-        this(createDockerClient(), metrics);
+        this(createDockerClient(), metrics, Clock.systemUTC());
     }
 
-    DockerEngine(DockerClient dockerClient, Metrics metrics) {
+    DockerEngine(DockerClient dockerClient, Metrics metrics, Clock clock) {
         this.dockerClient = dockerClient;
         this.dockerImageGC = new DockerImageGarbageCollector(this);
+        this.metrics = metrics;
+        this.clock = clock;
 
         numberOfDockerApiFails = metrics.declareCounter("docker.api_fails");
     }
@@ -347,10 +355,13 @@ public class DockerEngine implements ContainerEngine {
     }
 
     private class ImagePullCallback extends PullImageResultCallback {
+
         private final DockerImage dockerImage;
+        private final Instant startedAt;
 
         private ImagePullCallback(DockerImage dockerImage) {
             this.dockerImage = dockerImage;
+            this.startedAt = clock.instant();
         }
 
         @Override
@@ -359,7 +370,6 @@ public class DockerEngine implements ContainerEngine {
             logger.log(Level.SEVERE, "Could not download image " + dockerImage.asString(), throwable);
         }
 
-
         @Override
         public void onComplete() {
             if (imageIsDownloaded(dockerImage)) {
@@ -369,7 +379,16 @@ public class DockerEngine implements ContainerEngine {
                 numberOfDockerApiFails.increment();
                 throw new DockerClientException("Could not download image: " + dockerImage);
             }
+            sampleDuration();
         }
+
+        private void sampleDuration() {
+            Gauge gauge = metrics.declareGauge("docker.imagePullDurationSecs",
+                                               new Dimensions(Map.of("tag", dockerImage.tagAsVersion().toFullString())));
+            Duration pullDuration = Duration.between(startedAt, clock.instant());
+            gauge.sample(pullDuration.getSeconds());
+        }
+
     }
 
     // docker-java currently (3.0.8) does not support getting docker stats with stream=false, therefore we need
diff --git a/docker-api/src/test/java/com/yahoo/vespa/hosted/dockerapi/DockerEngineTest.java b/docker-api/src/test/java/com/yahoo/vespa/hosted/dockerapi/DockerEngineTest.java
index 69055e6402c..b6e9c4976bf 100644
--- a/docker-api/src/test/java/com/yahoo/vespa/hosted/dockerapi/DockerEngineTest.java
+++ b/docker-api/src/test/java/com/yahoo/vespa/hosted/dockerapi/DockerEngineTest.java
@@ -14,15 +14,20 @@ import com.github.dockerjava.api.command.PullImageCmd;
 import com.github.dockerjava.api.exception.NotFoundException;
 import com.github.dockerjava.core.command.ExecStartResultCallback;
 import com.yahoo.config.provision.DockerImage;
+import com.yahoo.test.ManualClock;
+import com.yahoo.vespa.hosted.dockerapi.metrics.DimensionMetrics;
 import com.yahoo.vespa.hosted.dockerapi.metrics.Metrics;
 import org.junit.Test;
 import org.mockito.ArgumentCaptor;
 import org.mockito.ArgumentMatchers;
 
+import java.time.Duration;
+import java.util.Optional;
 import java.util.OptionalLong;
 
 import static org.junit.Assert.assertEquals;
 import static org.junit.Assert.assertFalse;
+import static org.junit.Assert.assertNotNull;
 import static org.junit.Assert.assertTrue;
 import static org.mockito.ArgumentMatchers.any;
 import static org.mockito.ArgumentMatchers.eq;
@@ -36,7 +41,8 @@ public class DockerEngineTest {
 
     private final DockerClient dockerClient = mock(DockerClient.class);
     private final Metrics metrics = new Metrics();
-    private final DockerEngine docker = new DockerEngine(dockerClient, metrics);
+    private final ManualClock clock = new ManualClock();
+    private final DockerEngine docker = new DockerEngine(dockerClient, metrics, clock);
 
     @Test
     public void testExecuteCompletes() {
@@ -85,7 +91,6 @@ public class DockerEngineTest {
                 .thenThrow(new NotFoundException("Image not found"))
                 .thenReturn(inspectImageResponse);
 
-        // Array to make it final
         ArgumentCaptor<ResultCallback> resultCallback = ArgumentCaptor.forClass(ResultCallback.class);
         PullImageCmd pullImageCmd = mock(PullImageCmd.class);
         when(pullImageCmd.exec(resultCallback.capture())).thenReturn(null);
@@ -97,7 +102,9 @@ public class DockerEngineTest {
         assertTrue("Should return true, the pull i still ongoing", docker.pullImageAsyncIfNeeded(image, RegistryCredentials.none));
 
         assertTrue(docker.imageIsDownloaded(image));
+        clock.advance(Duration.ofMinutes(10));
         resultCallback.getValue().onComplete();
+        assertPullDuration(Duration.ofMinutes(10), "1.2.3");
         assertFalse(docker.pullImageAsyncIfNeeded(image, RegistryCredentials.none));
     }
 
@@ -109,7 +116,6 @@ public class DockerEngineTest {
         InspectImageCmd imageInspectCmd = mock(InspectImageCmd.class);
         when(imageInspectCmd.exec()).thenThrow(new NotFoundException("Image not found"));
 
-        // Array to make it final
         ArgumentCaptor<ResultCallback> resultCallback = ArgumentCaptor.forClass(ResultCallback.class);
         PullImageCmd pullImageCmd = mock(PullImageCmd.class);
         when(pullImageCmd.exec(resultCallback.capture())).thenReturn(null);
@@ -118,7 +124,7 @@ public class DockerEngineTest {
         when(dockerClient.pullImageCmd(eq(image.asString()))).thenReturn(pullImageCmd);
 
         assertTrue("Should return true, we just scheduled the pull", docker.pullImageAsyncIfNeeded(image, RegistryCredentials.none));
-        assertTrue("Should return true, the pull i still ongoing", docker.pullImageAsyncIfNeeded(image, RegistryCredentials.none));
+        assertTrue("Should return true, the pull is still ongoing", docker.pullImageAsyncIfNeeded(image, RegistryCredentials.none));
 
         try {
             resultCallback.getValue().onComplete();
@@ -128,4 +134,14 @@ public class DockerEngineTest {
         assertTrue("Should return true, new pull scheduled", docker.pullImageAsyncIfNeeded(image, RegistryCredentials.none));
     }
 
+    private void assertPullDuration(Duration duration, String tag) {
+        Optional<DimensionMetrics> byTag = metrics.getDefaultMetrics().stream()
+                                                  .filter(metrics -> tag.equals(metrics.getDimensions().asMap().get("tag")))
+                                                  .findFirst();
+        assertTrue("Found metric for tag=" + tag, byTag.isPresent());
+        Number durationInSecs = byTag.get().getMetrics().get("docker.imagePullDurationSecs");
+        assertNotNull(durationInSecs);
+        assertEquals(duration, Duration.ofSeconds(durationInSecs.longValue()));
+    }
+
 }