From eaa0a4ede51c5c0aee29deeb3f20dedaaf94404c Mon Sep 17 00:00:00 2001 From: Håkon Hallingstad Date: Tue, 22 Oct 2019 09:02:19 +0200 Subject: Revert "Revert "Add Orchestrator application lock metrics"" --- .../java/com/yahoo/jdisc/core/SystemTimer.java | 7 +++ .../main/java/com/yahoo/jdisc/test/TestTimer.java | 31 +++++++++++ .../node/admin/task/util/time/TestTimer.java | 29 ----------- .../task/util/process/ProcessFactoryImplTest.java | 2 +- .../status/ZookeeperStatusService.java | 60 +++++++++++++++++++--- .../vespa/orchestrator/OrchestratorImplTest.java | 7 ++- .../vespa/orchestrator/model/ModelTestUtils.java | 6 ++- .../orchestrator/resources/HostResourceTest.java | 5 +- .../status/ZookeeperStatusServiceTest.java | 46 +++++++++++++++-- 9 files changed, 150 insertions(+), 43 deletions(-) create mode 100644 jdisc_core/src/main/java/com/yahoo/jdisc/test/TestTimer.java delete mode 100644 node-admin/src/main/java/com/yahoo/vespa/hosted/node/admin/task/util/time/TestTimer.java diff --git a/jdisc_core/src/main/java/com/yahoo/jdisc/core/SystemTimer.java b/jdisc_core/src/main/java/com/yahoo/jdisc/core/SystemTimer.java index 15e234079b0..40fce9fec54 100644 --- a/jdisc_core/src/main/java/com/yahoo/jdisc/core/SystemTimer.java +++ b/jdisc_core/src/main/java/com/yahoo/jdisc/core/SystemTimer.java @@ -3,6 +3,8 @@ package com.yahoo.jdisc.core; import com.yahoo.jdisc.Timer; +import java.time.Instant; + /** * A timer which returns the System time * @@ -14,4 +16,9 @@ public class SystemTimer implements Timer { public long currentTimeMillis() { return System.currentTimeMillis(); } + + @Override + public Instant currentTime() { + return Instant.now(); + } } diff --git a/jdisc_core/src/main/java/com/yahoo/jdisc/test/TestTimer.java b/jdisc_core/src/main/java/com/yahoo/jdisc/test/TestTimer.java new file mode 100644 index 00000000000..4d274a33a1f --- /dev/null +++ b/jdisc_core/src/main/java/com/yahoo/jdisc/test/TestTimer.java @@ -0,0 +1,31 @@ +// Copyright 2018 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +package com.yahoo.jdisc.test; + +import com.yahoo.jdisc.Timer; + +import java.time.Duration; + +/** + * A {@link Timer} to be used in tests when the advancement of time needs to be controlled. + * + * @author hakonhall + */ +public class TestTimer implements Timer { + private Duration durationSinceEpoch = Duration.ZERO; + + public void setMillis(long millisSinceEpoch) { + durationSinceEpoch = Duration.ofMillis(millisSinceEpoch); + } + + public void advanceMillis(long millis) { advance(Duration.ofMillis(millis)); } + public void advanceSeconds(long seconds) { advance(Duration.ofSeconds(seconds)); } + public void advanceMinutes(long minutes) { advance(Duration.ofMinutes(minutes)); } + public void advance(Duration duration) { + durationSinceEpoch = durationSinceEpoch.plus(duration); + } + + @Override + public long currentTimeMillis() { + return durationSinceEpoch.toMillis(); + } +} diff --git a/node-admin/src/main/java/com/yahoo/vespa/hosted/node/admin/task/util/time/TestTimer.java b/node-admin/src/main/java/com/yahoo/vespa/hosted/node/admin/task/util/time/TestTimer.java deleted file mode 100644 index beadeeed4a3..00000000000 --- a/node-admin/src/main/java/com/yahoo/vespa/hosted/node/admin/task/util/time/TestTimer.java +++ /dev/null @@ -1,29 +0,0 @@ -// Copyright 2018 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. -package com.yahoo.vespa.hosted.node.admin.task.util.time; - -import com.yahoo.jdisc.Timer; - -import java.time.Duration; - -/** - * @author hakonhall - */ -public class TestTimer implements Timer { - private Duration durationSinceEpoch = Duration.ZERO; - - public void setMillis(long millisSinceEpoch) { - durationSinceEpoch = Duration.ofMillis(millisSinceEpoch); - } - - public void advanceMillis(long millis) { advance(Duration.ofMillis(millis)); } - public void advanceSeconds(long seconds) { advance(Duration.ofSeconds(seconds)); } - public void advanceMinutes(long minutes) { advance(Duration.ofMinutes(minutes)); } - public void advance(Duration duration) { - durationSinceEpoch = durationSinceEpoch.plus(duration); - } - - @Override - public long currentTimeMillis() { - return durationSinceEpoch.toMillis(); - } -} diff --git a/node-admin/src/test/java/com/yahoo/vespa/hosted/node/admin/task/util/process/ProcessFactoryImplTest.java b/node-admin/src/test/java/com/yahoo/vespa/hosted/node/admin/task/util/process/ProcessFactoryImplTest.java index e66b3a7aed2..09b6e65aca5 100644 --- a/node-admin/src/test/java/com/yahoo/vespa/hosted/node/admin/task/util/process/ProcessFactoryImplTest.java +++ b/node-admin/src/test/java/com/yahoo/vespa/hosted/node/admin/task/util/process/ProcessFactoryImplTest.java @@ -2,7 +2,7 @@ package com.yahoo.vespa.hosted.node.admin.task.util.process; import com.yahoo.vespa.hosted.node.admin.task.util.file.UnixPath; -import com.yahoo.vespa.hosted.node.admin.task.util.time.TestTimer; +import com.yahoo.jdisc.test.TestTimer; import org.junit.Test; import org.mockito.ArgumentCaptor; 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, Metric.Context> cachedContexts = new ConcurrentHashMap<>(); /** A cache of hosts allowed to be down. Access only through {@link #getValidCache()}! */ - private final Map> hostsDown; + private final Map> 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 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 applications = new HashMap<>(); private final ClusterControllerClientFactory clusterControllerClientFactory = new ClusterControllerClientFactoryMock(); private final Map 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> 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 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)) { -- cgit v1.2.3