Revert "Revert "Add Orchestrator application lock metrics""

5 files changed, 111 insertions, 13 deletions

diff --git a/orchestrator/src/main/java/com/yahoo/vespa/orchestrator/status/ZookeeperStatusService.java b/orchestrator/src/main/java/com/yahoo/vespa/orchestrator/status/ZookeeperStatusService.java
index e3d2a0827ed..65bdaed86b8 100644
--- a/orchestrator/src/main/java/com/yahoo/vespa/orchestrator/status/ZookeeperStatusService.java
+++ b/orchestrator/src/main/java/com/yahoo/vespa/orchestrator/status/ZookeeperStatusService.java
@@ -2,7 +2,10 @@
 package com.yahoo.vespa.orchestrator.status;
 
 import com.google.common.util.concurrent.UncheckedTimeoutException;
+import com.yahoo.config.provision.ApplicationId;
 import com.yahoo.container.jaxrs.annotation.Component;
+import com.yahoo.jdisc.Metric;
+import com.yahoo.jdisc.Timer;
 import com.yahoo.log.LogLevel;
 import com.yahoo.vespa.applicationmodel.ApplicationInstanceReference;
 import com.yahoo.vespa.applicationmodel.HostName;
@@ -17,6 +20,7 @@ import org.apache.zookeeper.data.Stat;
 
 import javax.inject.Inject;
 import java.time.Duration;
+import java.time.Instant;
 import java.util.Collections;
 import java.util.HashSet;
 import java.util.Map;
@@ -42,18 +46,27 @@ public class ZookeeperStatusService implements StatusService {
 
     private final Curator curator;
     private final CuratorCounter counter;
+    private final Metric metric;
+    private final Timer timer;
+
+    /**
+     * A cache of metric contexts for each possible dimension map. In practice, there is one dimension map
+     * for each application, so up to hundreds of elements.
+     */
+    private final ConcurrentHashMap<Map<String, String>, Metric.Context> cachedContexts = new ConcurrentHashMap<>();
 
     /** A cache of hosts allowed to be down. Access only through {@link #getValidCache()}! */
-    private final Map<ApplicationInstanceReference, Set<HostName>> hostsDown;
+    private final Map<ApplicationInstanceReference, Set<HostName>> hostsDown = new ConcurrentHashMap<>();
 
     private volatile long cacheRefreshedAt;
 
     @Inject
-    public ZookeeperStatusService(@Component Curator curator) {
+    public ZookeeperStatusService(@Component Curator curator, @Component Metric metric, @Component Timer timer) {
         this.curator = curator;
         this.counter = new CuratorCounter(curator, HOST_STATUS_CACHE_COUNTER_PATH);
         this.cacheRefreshedAt = counter.get();
-        this.hostsDown = new ConcurrentHashMap<>();
+        this.metric = metric;
+        this.timer = timer;
     }
 
     @Override
@@ -104,20 +117,51 @@ public class ZookeeperStatusService implements StatusService {
     public MutableStatusRegistry lockApplicationInstance_forCurrentThreadOnly(
             OrchestratorContext context,
             ApplicationInstanceReference applicationInstanceReference) throws UncheckedTimeoutException {
+        ApplicationId applicationId = OrchestratorUtil.toApplicationId(applicationInstanceReference);
+        String app = applicationId.application().value() + "." + applicationId.instance().value();
+        Map<String, String> dimensions = Map.of(
+                "tenantName", applicationId.tenant().value(),
+                "applicationId", applicationId.toFullString(),
+                "app", app);
+        Metric.Context metricContext = cachedContexts.computeIfAbsent(dimensions, metric::createContext);
+
         Duration duration = context.getTimeLeft();
         String lockPath = applicationInstanceLock2Path(applicationInstanceReference);
         Lock lock = new Lock(lockPath, curator);
-        lock.acquire(duration);
+
+        Instant startTime = timer.currentTime();
+        Instant acquireEndTime;
+        boolean lockAcquired = false;
+        try {
+            lock.acquire(duration);
+            lockAcquired = true;
+        } finally {
+            acquireEndTime = timer.currentTime();
+            double seconds = durationInSeconds(startTime, acquireEndTime);
+            metric.set("orchestrator.lock.acquire-latency", seconds, metricContext);
+            metric.set("orchestrator.lock.acquired", lockAcquired ? 1 : 0, metricContext);
+        }
+
+        Runnable updateLockHoldMetric = () -> {
+            Instant lockReleasedTime = timer.currentTime();
+            double seconds = durationInSeconds(acquireEndTime, lockReleasedTime);
+            metric.set("orchestrator.lock.hold-latency", seconds, metricContext);
+        };
 
         try {
-            return new ZkMutableStatusRegistry(lock, applicationInstanceReference, context.isProbe());
+            return new ZkMutableStatusRegistry(lock, applicationInstanceReference, context.isProbe(), updateLockHoldMetric);
         } catch (Throwable t) {
             // In case the constructor throws an exception.
+            updateLockHoldMetric.run();
             lock.close();
             throw t;
         }
     }
 
+    private double durationInSeconds(Instant startInstant, Instant endInstant) {
+        return Duration.between(startInstant, endInstant).toMillis() / 1000.0;
+    }
+
     private void setHostStatus(ApplicationInstanceReference applicationInstanceReference,
                                HostName hostName,
                                HostStatus status) {
@@ -237,13 +281,16 @@ public class ZookeeperStatusService implements StatusService {
         private final Lock lock;
         private final ApplicationInstanceReference applicationInstanceReference;
         private final boolean probe;
+        private final Runnable onLockRelease;
 
         public ZkMutableStatusRegistry(Lock lock,
                                        ApplicationInstanceReference applicationInstanceReference,
-                                       boolean probe) {
+                                       boolean probe,
+                                       Runnable onLockRelease) {
             this.lock = lock;
             this.applicationInstanceReference = applicationInstanceReference;
             this.probe = probe;
+            this.onLockRelease = onLockRelease;
         }
 
         @Override
@@ -293,6 +340,7 @@ public class ZookeeperStatusService implements StatusService {
 
         @Override
         public void close()  {
+            onLockRelease.run();
             try {
                 lock.close();
             } catch (RuntimeException e) {
diff --git a/orchestrator/src/test/java/com/yahoo/vespa/orchestrator/OrchestratorImplTest.java b/orchestrator/src/test/java/com/yahoo/vespa/orchestrator/OrchestratorImplTest.java
index af93d497677..4d7a0f18918 100644
--- a/orchestrator/src/test/java/com/yahoo/vespa/orchestrator/OrchestratorImplTest.java
+++ b/orchestrator/src/test/java/com/yahoo/vespa/orchestrator/OrchestratorImplTest.java
@@ -2,6 +2,8 @@
 package com.yahoo.vespa.orchestrator;
 
 import com.yahoo.config.provision.ApplicationId;
+import com.yahoo.jdisc.Metric;
+import com.yahoo.jdisc.test.TestTimer;
 import com.yahoo.vespa.applicationmodel.ApplicationInstance;
 import com.yahoo.vespa.applicationmodel.ApplicationInstanceId;
 import com.yahoo.vespa.applicationmodel.ApplicationInstanceReference;
@@ -49,6 +51,7 @@ import static org.mockito.ArgumentMatchers.any;
 import static org.mockito.ArgumentMatchers.eq;
 import static org.mockito.Mockito.doThrow;
 import static org.mockito.Mockito.inOrder;
+import static org.mockito.Mockito.mock;
 import static org.mockito.Mockito.spy;
 
 /**
@@ -77,7 +80,7 @@ public class OrchestratorImplTest {
         clustercontroller = new ClusterControllerClientFactoryMock();
         orchestrator = new OrchestratorImpl(
                 clustercontroller,
-                new ZookeeperStatusService(new MockCurator()),
+                new ZookeeperStatusService(new MockCurator(), mock(Metric.class), new TestTimer()),
                 new OrchestratorConfig(new OrchestratorConfig.Builder()),
                 new DummyInstanceLookupService());
 
@@ -311,7 +314,7 @@ public class OrchestratorImplTest {
     @Test
     public void testGetHost() throws Exception {
         ClusterControllerClientFactory clusterControllerClientFactory = new ClusterControllerClientFactoryMock();
-        StatusService statusService = new ZookeeperStatusService(new MockCurator());
+        StatusService statusService = new ZookeeperStatusService(new MockCurator(), mock(Metric.class), new TestTimer());
 
         HostName hostName = new HostName("host.yahoo.com");
         TenantId tenantId = new TenantId("tenant");
diff --git a/orchestrator/src/test/java/com/yahoo/vespa/orchestrator/model/ModelTestUtils.java b/orchestrator/src/test/java/com/yahoo/vespa/orchestrator/model/ModelTestUtils.java
index 0def668e147..544ac27c92f 100644
--- a/orchestrator/src/test/java/com/yahoo/vespa/orchestrator/model/ModelTestUtils.java
+++ b/orchestrator/src/test/java/com/yahoo/vespa/orchestrator/model/ModelTestUtils.java
@@ -1,6 +1,8 @@
 // Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
 package com.yahoo.vespa.orchestrator.model;
 
+import com.yahoo.jdisc.Metric;
+import com.yahoo.jdisc.test.TestTimer;
 import com.yahoo.vespa.applicationmodel.ApplicationInstance;
 import com.yahoo.vespa.applicationmodel.ApplicationInstanceId;
 import com.yahoo.vespa.applicationmodel.ApplicationInstanceReference;
@@ -36,12 +38,14 @@ import java.util.List;
 import java.util.Map;
 import java.util.Set;
 
+import static org.mockito.Mockito.mock;
+
 class ModelTestUtils {
 
     private final Map<ApplicationInstanceReference, ApplicationInstance> applications = new HashMap<>();
     private final ClusterControllerClientFactory clusterControllerClientFactory = new ClusterControllerClientFactoryMock();
     private final Map<HostName, HostStatus> hostStatusMap = new HashMap<>();
-    private final StatusService statusService = new ZookeeperStatusService(new MockCurator());
+    private final StatusService statusService = new ZookeeperStatusService(new MockCurator(), mock(Metric.class), new TestTimer());
     private final Orchestrator orchestrator = new OrchestratorImpl(clusterControllerClientFactory,
                                                                    statusService,
                                                                    new OrchestratorConfig(new Builder()),
diff --git a/orchestrator/src/test/java/com/yahoo/vespa/orchestrator/resources/HostResourceTest.java b/orchestrator/src/test/java/com/yahoo/vespa/orchestrator/resources/HostResourceTest.java
index bbc526cfbe1..32758970d75 100644
--- a/orchestrator/src/test/java/com/yahoo/vespa/orchestrator/resources/HostResourceTest.java
+++ b/orchestrator/src/test/java/com/yahoo/vespa/orchestrator/resources/HostResourceTest.java
@@ -2,6 +2,8 @@
 package com.yahoo.vespa.orchestrator.resources;
 
 import com.google.common.util.concurrent.UncheckedTimeoutException;
+import com.yahoo.jdisc.Metric;
+import com.yahoo.jdisc.test.TestTimer;
 import com.yahoo.vespa.applicationmodel.ApplicationInstance;
 import com.yahoo.vespa.applicationmodel.ApplicationInstanceId;
 import com.yahoo.vespa.applicationmodel.ApplicationInstanceReference;
@@ -72,7 +74,8 @@ public class HostResourceTest {
     private static final int SERVICE_MONITOR_CONVERGENCE_LATENCY_SECONDS = 0;
     private static final TenantId TENANT_ID = new TenantId("tenantId");
     private static final ApplicationInstanceId APPLICATION_INSTANCE_ID = new ApplicationInstanceId("applicationId");
-    private static final StatusService EVERY_HOST_IS_UP_HOST_STATUS_SERVICE = new ZookeeperStatusService(new MockCurator());
+    private static final StatusService EVERY_HOST_IS_UP_HOST_STATUS_SERVICE = new ZookeeperStatusService(
+            new MockCurator(), mock(Metric.class), new TestTimer());
 
     private static final InstanceLookupService mockInstanceLookupService = mock(InstanceLookupService.class);
     static {
diff --git a/orchestrator/src/test/java/com/yahoo/vespa/orchestrator/status/ZookeeperStatusServiceTest.java b/orchestrator/src/test/java/com/yahoo/vespa/orchestrator/status/ZookeeperStatusServiceTest.java
index 9b1be12121d..707c81b92a5 100644
--- a/orchestrator/src/test/java/com/yahoo/vespa/orchestrator/status/ZookeeperStatusServiceTest.java
+++ b/orchestrator/src/test/java/com/yahoo/vespa/orchestrator/status/ZookeeperStatusServiceTest.java
@@ -1,6 +1,9 @@
 // Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
 package com.yahoo.vespa.orchestrator.status;
 
+import com.yahoo.jdisc.Metric;
+import com.yahoo.jdisc.Timer;
+import com.yahoo.jdisc.test.TestTimer;
 import com.yahoo.log.LogLevel;
 import com.yahoo.vespa.applicationmodel.ApplicationInstanceReference;
 import com.yahoo.vespa.curator.Curator;
@@ -16,12 +19,18 @@ import org.hamcrest.TypeSafeMatcher;
 import org.junit.After;
 import org.junit.Before;
 import org.junit.Test;
+import org.junit.runner.RunWith;
+import org.mockito.ArgumentCaptor;
+import org.mockito.Captor;
+import org.mockito.junit.MockitoJUnitRunner;
 
 import java.time.Duration;
+import java.time.Instant;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.Collections;
 import java.util.List;
+import java.util.Map;
 import java.util.Optional;
 import java.util.Set;
 import java.util.concurrent.CompletableFuture;
@@ -33,26 +42,37 @@ import java.util.logging.Logger;
 
 import static org.hamcrest.core.Is.is;
 import static org.hamcrest.core.IsCollectionContaining.hasItem;
+import static org.junit.Assert.assertEquals;
 import static org.junit.Assert.assertThat;
 import static org.junit.Assert.fail;
+import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.ArgumentMatchers.eq;
 import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.verify;
 import static org.mockito.Mockito.when;
 
+@RunWith(MockitoJUnitRunner.class)
 public class ZookeeperStatusServiceTest {
     private TestingServer testingServer;
     private ZookeeperStatusService zookeeperStatusService;
     private Curator curator;
+    private final Timer timer = mock(Timer.class);
+    private final Metric metric = mock(Metric.class);
     private final OrchestratorContext context = mock(OrchestratorContext.class);
 
+    @Captor
+    private ArgumentCaptor<Map<String, String>> captor;
+
     @Before
     public void setUp() throws Exception {
         Logger.getLogger("").setLevel(LogLevel.WARNING);
 
         testingServer = new TestingServer();
         curator = createConnectedCurator(testingServer);
-        zookeeperStatusService = new ZookeeperStatusService(curator);
+        zookeeperStatusService = new ZookeeperStatusService(curator, metric, timer);
         when(context.getTimeLeft()).thenReturn(Duration.ofSeconds(10));
         when(context.isProbe()).thenReturn(false);
+        when(timer.currentTime()).thenReturn(Instant.ofEpochMilli(1));
     }
 
     private static Curator createConnectedCurator(TestingServer server) throws InterruptedException {
@@ -81,6 +101,11 @@ public class ZookeeperStatusServiceTest {
 
     @Test
     public void setting_host_state_is_idempotent() {
+        when(timer.currentTime()).thenReturn(
+                Instant.ofEpochMilli((1)),
+                Instant.ofEpochMilli((3)),
+                Instant.ofEpochMilli(6));
+
         try (MutableStatusRegistry statusRegistry = zookeeperStatusService
                 .lockApplicationInstance_forCurrentThreadOnly(context, TestIds.APPLICATION_INSTANCE_REFERENCE)) {
 
@@ -96,11 +121,26 @@ public class ZookeeperStatusServiceTest {
                 }
             }
         }
+
+        // Time
+        //   1    Start before lock
+        //   3    After acquire => orchestrator.lock.acquire-latency = 3ms - 1ms
+        //   6    After release => orchestrator.lock.hold-latency = 6ms - 3ms
+        verify(metric).set(eq("orchestrator.lock.acquire-latency"), eq(0.002), any());
+        verify(metric).set(eq("orchestrator.lock.acquired"), eq(1), any());
+        verify(metric).set(eq("orchestrator.lock.hold-latency"), eq(0.003), any());
+        verify(metric).createContext(captor.capture());
+
+        assertEquals(
+                Map.of("app", "test-application.test-instance-key",
+                        "tenantName", "test-tenant",
+                        "applicationId", "test-tenant.test-application.test-instance-key"),
+                captor.getValue());
     }
 
     @Test
     public void locks_are_exclusive() throws Exception {
-        ZookeeperStatusService zookeeperStatusService2 = new ZookeeperStatusService(curator);
+        ZookeeperStatusService zookeeperStatusService2 = new ZookeeperStatusService(curator, mock(Metric.class), new TestTimer());
 
         final CompletableFuture<Void> lockedSuccessfullyFuture;
         try (MutableStatusRegistry statusRegistry = zookeeperStatusService
@@ -125,7 +165,7 @@ public class ZookeeperStatusServiceTest {
 
     @Test
     public void failing_to_get_lock_closes_SessionFailRetryLoop() throws Exception {
-        ZookeeperStatusService zookeeperStatusService2 = new ZookeeperStatusService(curator);
+        ZookeeperStatusService zookeeperStatusService2 = new ZookeeperStatusService(curator, mock(Metric.class), new TestTimer());
 
         try (MutableStatusRegistry statusRegistry = zookeeperStatusService
                 .lockApplicationInstance_forCurrentThreadOnly(context, TestIds.APPLICATION_INSTANCE_REFERENCE)) {