Merge pull request #11883 from vespa-engine/jvenstad/prepare-and-activate-metrics

Emit metrics with prepare and activate time whenever this occurs

5 files changed, 176 insertions, 47 deletions

diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/ApplicationRepository.java b/configserver/src/main/java/com/yahoo/vespa/config/server/ApplicationRepository.java
index 1d7bc59454e..3af7c7fdacc 100644
--- a/configserver/src/main/java/com/yahoo/vespa/config/server/ApplicationRepository.java
+++ b/configserver/src/main/java/com/yahoo/vespa/config/server/ApplicationRepository.java
@@ -21,7 +21,9 @@ import com.yahoo.config.provision.SystemName;
 import com.yahoo.config.provision.TenantName;
 import com.yahoo.config.provision.Zone;
 import com.yahoo.container.jdisc.HttpResponse;
+import com.yahoo.docproc.jdisc.metric.NullMetric;
 import com.yahoo.io.IOUtils;
+import com.yahoo.jdisc.Metric;
 import com.yahoo.log.LogLevel;
 import com.yahoo.path.Path;
 import com.yahoo.slime.Slime;
@@ -75,6 +77,7 @@ import java.util.Arrays;
 import java.util.Collection;
 import java.util.HashSet;
 import java.util.List;
+import java.util.Map;
 import java.util.Optional;
 import java.util.Set;
 import java.util.logging.Level;
@@ -110,6 +113,7 @@ public class ApplicationRepository implements com.yahoo.config.provision.Deploye
     private final Orchestrator orchestrator;
     private final LogRetriever logRetriever;
     private final TesterClient testerClient;
+    private final Metric metric;
 
     @Inject
     public ApplicationRepository(TenantRepository tenantRepository,
@@ -119,7 +123,8 @@ public class ApplicationRepository implements com.yahoo.config.provision.Deploye
                                  HttpProxy httpProxy,
                                  ConfigserverConfig configserverConfig,
                                  Orchestrator orchestrator,
-                                 TesterClient testerClient) {
+                                 TesterClient testerClient,
+                                 Metric metric) {
         this(tenantRepository,
              hostProvisionerProvider.getHostProvisioner(),
              infraDeployerProvider.getInfraDeployer(),
@@ -130,7 +135,8 @@ public class ApplicationRepository implements com.yahoo.config.provision.Deploye
              new LogRetriever(),
              new FileDistributionStatus(),
              Clock.systemUTC(),
-             testerClient);
+             testerClient,
+             metric);
     }
 
     // For testing
@@ -144,7 +150,8 @@ public class ApplicationRepository implements com.yahoo.config.provision.Deploye
              new ConfigserverConfig(new ConfigserverConfig.Builder()),
              new LogRetriever(),
              clock,
-             new TesterClient());
+             new TesterClient(),
+             new NullMetric());
     }
 
     // For testing
@@ -154,7 +161,8 @@ public class ApplicationRepository implements com.yahoo.config.provision.Deploye
                                  ConfigserverConfig configserverConfig,
                                  LogRetriever logRetriever,
                                  Clock clock,
-                                 TesterClient testerClient) {
+                                 TesterClient testerClient,
+                                 Metric metric) {
         this(tenantRepository,
              Optional.of(hostProvisioner),
              Optional.empty(),
@@ -165,7 +173,8 @@ public class ApplicationRepository implements com.yahoo.config.provision.Deploye
              logRetriever,
              new FileDistributionStatus(),
              clock,
-             testerClient);
+             testerClient,
+             metric);
     }
 
     private ApplicationRepository(TenantRepository tenantRepository,
@@ -178,7 +187,8 @@ public class ApplicationRepository implements com.yahoo.config.provision.Deploye
                                   LogRetriever logRetriever,
                                   FileDistributionStatus fileDistributionStatus,
                                   Clock clock,
-                                  TesterClient testerClient) {
+                                  TesterClient testerClient,
+                                  Metric metric) {
         this.tenantRepository = tenantRepository;
         this.hostProvisioner = hostProvisioner;
         this.infraDeployer = infraDeployer;
@@ -190,6 +200,7 @@ public class ApplicationRepository implements com.yahoo.config.provision.Deploye
         this.fileDistributionStatus = fileDistributionStatus;
         this.clock = clock;
         this.testerClient = testerClient;
+        this.metric = metric;
     }
 
     // ---------------- Deploying ----------------------------------------------------------------
@@ -201,10 +212,12 @@ public class ApplicationRepository implements com.yahoo.config.provision.Deploye
         Optional<ApplicationSet> currentActiveApplicationSet = getCurrentActiveApplicationSet(tenant, applicationId);
         Slime deployLog = createDeployLog();
         DeployLogger logger = new DeployHandlerLogger(deployLog.get().setArray("log"), prepareParams.isVerbose(), applicationId);
-        ConfigChangeActions actions = session.prepare(logger, prepareParams, currentActiveApplicationSet, tenant.getPath(), now);
-        logConfigChangeActions(actions, logger);
-        log.log(LogLevel.INFO, TenantRepository.logPre(applicationId) + "Session " + sessionId + " prepared successfully. ");
-        return new PrepareResult(sessionId, actions, deployLog);
+        try (ActionTimer timer = timerFor(applicationId, "deployment.prepareMillis")) {
+            ConfigChangeActions actions = session.prepare(logger, prepareParams, currentActiveApplicationSet, tenant.getPath(), now);
+            logConfigChangeActions(actions, logger);
+            log.log(LogLevel.INFO, TenantRepository.logPre(applicationId) + "Session " + sessionId + " prepared successfully. ");
+            return new PrepareResult(sessionId, actions, deployLog);
+        }
     }
 
     public PrepareResult prepareAndActivate(Tenant tenant, long sessionId, PrepareParams prepareParams,
@@ -848,4 +861,42 @@ public class ApplicationRepository implements com.yahoo.config.provision.Deploye
                         RegionName.from(configserverConfig.region()));
     }
 
+    /** Emits as a metric the time in millis spent while holding this timer, with deployment ID as dimensions. */
+    public ActionTimer timerFor(ApplicationId id, String metricName) {
+        return new ActionTimer(metric, clock, id, configserverConfig.environment(), configserverConfig.region(), metricName);
+    }
+
+    public static class ActionTimer implements AutoCloseable {
+
+        private final Metric metric;
+        private final Clock clock;
+        private final ApplicationId id;
+        private final String environment;
+        private final String region;
+        private final String name;
+        private final Instant start;
+
+        private ActionTimer(Metric metric, Clock clock, ApplicationId id, String environment, String region, String name) {
+            this.metric = metric;
+            this.clock = clock;
+            this.id = id;
+            this.environment = environment;
+            this.region = region;
+            this.name = name;
+            this.start = clock.instant();
+        }
+
+        @Override
+        public void close() {
+            metric.set(name,
+                       Duration.between(start, clock.instant()).toMillis(),
+                       metric.createContext(Map.of("tenant", id.tenant().value(),
+                                                   "application", id.application().value(),
+                                                   "instance", id.instance().value(),
+                                                   "environment", environment,
+                                                   "region", region)));
+        }
+
+    }
+
 }
diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/deploy/Deployment.java b/configserver/src/main/java/com/yahoo/vespa/config/server/deploy/Deployment.java
index 9e81d3c0525..89d7c349d6b 100644
--- a/configserver/src/main/java/com/yahoo/vespa/config/server/deploy/Deployment.java
+++ b/configserver/src/main/java/com/yahoo/vespa/config/server/deploy/Deployment.java
@@ -6,11 +6,14 @@ import com.yahoo.config.application.api.DeployLogger;
 import com.yahoo.config.provision.ApplicationId;
 import com.yahoo.config.provision.HostFilter;
 import com.yahoo.config.provision.Provisioner;
+import com.yahoo.config.provision.zone.ZoneId;
+import com.yahoo.jdisc.Metric;
 import com.yahoo.log.LogLevel;
 import com.yahoo.transaction.NestedTransaction;
 import com.yahoo.transaction.Transaction;
 import com.yahoo.vespa.config.server.ActivationConflictException;
 import com.yahoo.vespa.config.server.ApplicationRepository;
+import com.yahoo.vespa.config.server.ApplicationRepository.ActionTimer;
 import com.yahoo.vespa.config.server.TimeoutBudget;
 import com.yahoo.vespa.config.server.http.InternalServerException;
 import com.yahoo.vespa.config.server.session.LocalSession;
@@ -22,6 +25,7 @@ import com.yahoo.vespa.curator.Lock;
 
 import java.time.Clock;
 import java.time.Duration;
+import java.time.Instant;
 import java.util.Optional;
 import java.util.logging.Logger;
 
@@ -98,19 +102,21 @@ public class Deployment implements com.yahoo.config.provision.Deployment {
     @Override
     public void prepare() {
         if (prepared) return;
-        TimeoutBudget timeoutBudget = new TimeoutBudget(clock, timeout);
-
-        session.prepare(logger,
-                        new PrepareParams.Builder().applicationId(session.getApplicationId())
-                                                   .timeoutBudget(timeoutBudget)
-                                                   .ignoreValidationErrors( ! validate)
-                                                   .vespaVersion(version.toString())
-                                                   .isBootstrap(isBootstrap)
-                                                   .build(),
-                        Optional.empty(),
-                        tenant.getPath(),
-                        clock.instant());
-        this.prepared = true;
+        try (ActionTimer timer = applicationRepository.timerFor(session.getApplicationId(), "deployment.prepareMillis")) {
+            TimeoutBudget timeoutBudget = new TimeoutBudget(clock, timeout);
+
+            session.prepare(logger,
+                            new PrepareParams.Builder().applicationId(session.getApplicationId())
+                                                       .timeoutBudget(timeoutBudget)
+                                                       .ignoreValidationErrors(!validate)
+                                                       .vespaVersion(version.toString())
+                                                       .isBootstrap(isBootstrap)
+                                                       .build(),
+                            Optional.empty(),
+                            tenant.getPath(),
+                            clock.instant());
+            this.prepared = true;
+        }
     }
 
     /** Activates this. If it is not already prepared, this will call prepare first. */
@@ -119,28 +125,32 @@ public class Deployment implements com.yahoo.config.provision.Deployment {
         if ( ! prepared)
             prepare();
 
-        TimeoutBudget timeoutBudget = new TimeoutBudget(clock, timeout);
-
-        ApplicationId applicationId = session.getApplicationId();
-        try (Lock lock = tenant.getApplicationRepo().lock(applicationId)) {
-            validateSessionStatus(session);
-            NestedTransaction transaction = new NestedTransaction();
-            transaction.add(deactivateCurrentActivateNew(applicationRepository.getActiveSession(applicationId), session, ignoreSessionStaleFailure));
-            hostProvisioner.ifPresent(provisioner -> provisioner.activate(transaction, applicationId, session.getAllocatedHosts().getHosts()));
-            transaction.commit();
-        } catch (RuntimeException e) {
-            throw e;
-        } catch (Exception e) {
-            throw new InternalServerException("Error activating application", e);
-        }
+        try (ActionTimer timer = applicationRepository.timerFor(session.getApplicationId(), "deployment.activateMillis")) {
+            TimeoutBudget timeoutBudget = new TimeoutBudget(clock, timeout);
 
-        session.waitUntilActivated(timeoutBudget);
+            ApplicationId applicationId = session.getApplicationId();
+            try (Lock lock = tenant.getApplicationRepo().lock(applicationId)) {
+                validateSessionStatus(session);
+                NestedTransaction transaction = new NestedTransaction();
+                transaction.add(deactivateCurrentActivateNew(applicationRepository.getActiveSession(applicationId), session, ignoreSessionStaleFailure));
+                hostProvisioner.ifPresent(provisioner -> provisioner.activate(transaction, applicationId, session.getAllocatedHosts().getHosts()));
+                transaction.commit();
+            }
+            catch (RuntimeException e) {
+                throw e;
+            }
+            catch (Exception e) {
+                throw new InternalServerException("Error activating application", e);
+            }
+
+            session.waitUntilActivated(timeoutBudget);
 
-        log.log(LogLevel.INFO, session.logPre() + "Session " + session.getSessionId() +
-                               " activated successfully using " +
-                               (hostProvisioner.isPresent() ? hostProvisioner.get() : "no host provisioner") +
-                               ". Config generation " + session.getMetaData().getGeneration() +
-                               ". File references used: " + applicationRepository.getFileReferences(applicationId));
+            log.log(LogLevel.INFO, session.logPre() + "Session " + session.getSessionId() +
+                                   " activated successfully using " +
+                                   (hostProvisioner.isPresent() ? hostProvisioner.get() : "no host provisioner") +
+                                   ". Config generation " + session.getMetaData().getGeneration() +
+                                   ". File references used: " + applicationRepository.getFileReferences(applicationId));
+        }
     }
 
     /**
diff --git a/configserver/src/test/java/com/yahoo/vespa/config/server/ApplicationRepositoryTest.java b/configserver/src/test/java/com/yahoo/vespa/config/server/ApplicationRepositoryTest.java
index d924d22cb39..a963252d7ca 100644
--- a/configserver/src/test/java/com/yahoo/vespa/config/server/ApplicationRepositoryTest.java
+++ b/configserver/src/test/java/com/yahoo/vespa/config/server/ApplicationRepositoryTest.java
@@ -12,7 +12,9 @@ import com.yahoo.config.provision.InstanceName;
 import com.yahoo.config.provision.Provisioner;
 import com.yahoo.config.provision.TenantName;
 import com.yahoo.container.jdisc.HttpResponse;
+import com.yahoo.docproc.jdisc.metric.NullMetric;
 import com.yahoo.io.IOUtils;
+import com.yahoo.jdisc.Metric;
 import com.yahoo.test.ManualClock;
 import com.yahoo.text.Utf8;
 import com.yahoo.vespa.config.server.application.OrchestratorMock;
@@ -40,6 +42,8 @@ import java.time.Instant;
 import java.util.ArrayList;
 import java.util.Collection;
 import java.util.Collections;
+import java.util.HashMap;
+import java.util.Map;
 import java.util.Optional;
 import java.util.Set;
 
@@ -326,6 +330,29 @@ public class ApplicationRepositoryTest {
         assertEquals(0, applicationRepository.deleteExpiredRemoteSessions(Duration.ofSeconds(0)));
     }
 
+    @Test
+    public void testMetrics() {
+        MockMetric actual = new MockMetric();
+        applicationRepository = new ApplicationRepository(tenantRepository,
+                                                          provisioner,
+                                                          orchestrator,
+                                                          new ConfigserverConfig(new ConfigserverConfig.Builder()),
+                                                          new MockLogRetriever(),
+                                                          new ManualClock(),
+                                                          new MockTesterClient(),
+                                                          actual);
+        deployApp(testAppLogServerWithContainer);
+        Map<String, ?> context = Map.of("tenant", "test1",
+                                        "application", "testapp",
+                                        "instance", "default",
+                                        "environment", "prod",
+                                        "region", "default");
+        MockMetric expected = new MockMetric();
+        expected.set("deployment.prepareMillis", 0L, expected.createContext(context));
+        expected.set("deployment.activateMillis", 0L, expected.createContext(context));
+        assertEquals(expected.values, actual.values);
+    }
+
     private ApplicationRepository createApplicationRepository() {
         return new ApplicationRepository(tenantRepository,
                                          provisioner,
@@ -333,7 +360,8 @@ public class ApplicationRepositoryTest {
                                          new ConfigserverConfig(new ConfigserverConfig.Builder()),
                                          new MockLogRetriever(),
                                          clock,
-                                         new MockTesterClient());
+                                         new MockTesterClient(),
+                                         new NullMetric());
     }
 
     private PrepareResult prepareAndActivateApp(File application) throws IOException {
@@ -369,4 +397,39 @@ public class ApplicationRepositoryTest {
         return applicationRepository.getMetadataFromSession(tenant, sessionId);
     }
 
+
+    /** Stores all added or set values for each metric and context. */
+    static class MockMetric implements Metric {
+
+        final Map<String, Map<Map<String, ?>, Number>> values = new HashMap<>();
+
+        @Override
+        public void set(String key, Number val, Metric.Context ctx) {
+            values.putIfAbsent(key, new HashMap<>());
+            values.get(key).put(((Context) ctx).point, val);
+        }
+
+        @Override
+        public void add(String key, Number val, Metric.Context ctx) {
+            throw new UnsupportedOperationException();
+        }
+
+        @Override
+        public Context createContext(Map<String, ?> properties) {
+            return new Context(properties);
+        }
+
+
+        private static class Context implements Metric.Context {
+
+            private final Map<String, ?> point;
+
+            public Context(Map<String, ?> point) {
+                this.point = Map.copyOf(point);
+            }
+
+        }
+
+    }
+
 }
diff --git a/configserver/src/test/java/com/yahoo/vespa/config/server/deploy/DeployTester.java b/configserver/src/test/java/com/yahoo/vespa/config/server/deploy/DeployTester.java
index 9a15d6528ee..32b704dd551 100644
--- a/configserver/src/test/java/com/yahoo/vespa/config/server/deploy/DeployTester.java
+++ b/configserver/src/test/java/com/yahoo/vespa/config/server/deploy/DeployTester.java
@@ -27,6 +27,7 @@ import com.yahoo.config.provision.Provisioner;
 import com.yahoo.config.provision.TenantName;
 import com.yahoo.component.Version;
 import com.yahoo.config.provision.Zone;
+import com.yahoo.docproc.jdisc.metric.NullMetric;
 import com.yahoo.transaction.NestedTransaction;
 import com.yahoo.vespa.config.server.ApplicationRepository;
 import com.yahoo.vespa.config.server.MockTesterClient;
@@ -137,7 +138,8 @@ public class DeployTester {
                                                           configserverConfig,
                                                           new LogRetriever(),
                                                           clock,
-                                                          new MockTesterClient());
+                                                          new MockTesterClient(),
+                                                          new NullMetric());
     }
 
     public Tenant tenant() {
diff --git a/configserver/src/test/java/com/yahoo/vespa/config/server/http/v2/ApplicationHandlerTest.java b/configserver/src/test/java/com/yahoo/vespa/config/server/http/v2/ApplicationHandlerTest.java
index 9e8d483cd86..438ccc5d783 100644
--- a/configserver/src/test/java/com/yahoo/vespa/config/server/http/v2/ApplicationHandlerTest.java
+++ b/configserver/src/test/java/com/yahoo/vespa/config/server/http/v2/ApplicationHandlerTest.java
@@ -9,6 +9,7 @@ import com.yahoo.config.provision.TenantName;
 import com.yahoo.config.provision.Zone;
 import com.yahoo.container.jdisc.HttpRequest;
 import com.yahoo.container.jdisc.HttpResponse;
+import com.yahoo.docproc.jdisc.metric.NullMetric;
 import com.yahoo.jdisc.Response;
 import com.yahoo.vespa.config.server.ApplicationRepository;
 import com.yahoo.vespa.config.server.MockLogRetriever;
@@ -79,7 +80,8 @@ public class ApplicationHandlerTest {
                                                           new ConfigserverConfig(new ConfigserverConfig.Builder()),
                                                           new MockLogRetriever(),
                                                           Clock.systemUTC(),
-                                                          new MockTesterClient());
+                                                          new MockTesterClient(),
+                                                          new NullMetric());
         listApplicationsHandler = new ListApplicationsHandler(ListApplicationsHandler.testOnlyContext(),
                                                               tenantRepository,
                                                               Zone.defaultZone());
@@ -177,7 +179,8 @@ public class ApplicationHandlerTest {
                                                                                 mockHttpProxy,
                                                                                 new ConfigserverConfig(new ConfigserverConfig.Builder()),
                                                                                 new OrchestratorMock(),
-                                                                                new MockTesterClient());
+                                                                                new MockTesterClient(),
+                                                                                new NullMetric());
         ApplicationHandler mockHandler = createApplicationHandler(applicationRepository);
         when(mockHttpProxy.get(any(), eq(host), eq(CLUSTERCONTROLLER_CONTAINER.serviceName),eq("clustercontroller-status/v1/clusterName1")))
                 .thenReturn(new StaticResponse(200, "text/html", "<html>...</html>"));