Avoid metrics on reentry of lock

5 files changed, 114 insertions, 61 deletions

diff --git a/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockAttempt.java b/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockAttempt.java
index 1478b36d331..9cf490bf8c6 100644
--- a/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockAttempt.java
+++ b/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockAttempt.java
@@ -21,19 +21,21 @@ public class LockAttempt {
     private final String lockPath;
     private final Instant callAcquireInstant;
     private final Duration timeout;
+    private final boolean reentry;
     private final LockMetrics lockMetrics;
     private final List<LockAttempt> nestedLockAttempts = new ArrayList<>();
     private final LatencyStats.ActiveInterval activeAcquireInterval;
     // Only accessed by mutating thread:
-    private LatencyStats.ActiveInterval activeLockedInterval = null;
+    private Optional<LatencyStats.ActiveInterval> activeLockedInterval = Optional.empty();
 
     private volatile Optional<Instant> lockAcquiredInstant = Optional.empty();
     private volatile Optional<Instant> terminalStateInstant = Optional.empty();
     private volatile Optional<String> stackTrace = Optional.empty();
 
     public static LockAttempt invokingAcquire(ThreadLockStats threadLockStats, String lockPath,
-                                              Duration timeout, LockMetrics lockMetrics) {
-        return new LockAttempt(threadLockStats, lockPath, timeout, Instant.now(), lockMetrics);
+                                              Duration timeout, LockMetrics lockMetrics,
+                                              boolean reentry) {
+        return new LockAttempt(threadLockStats, lockPath, timeout, Instant.now(), lockMetrics, reentry);
     }
 
     public enum LockState {
@@ -50,13 +52,14 @@ public class LockAttempt {
     private volatile LockState lockState = LockState.ACQUIRING;
 
     private LockAttempt(ThreadLockStats threadLockStats, String lockPath, Duration timeout,
-                        Instant callAcquireInstant, LockMetrics lockMetrics) {
+                        Instant callAcquireInstant, LockMetrics lockMetrics, boolean reentry) {
         this.threadLockStats = threadLockStats;
         this.lockPath = lockPath;
         this.callAcquireInstant = callAcquireInstant;
         this.timeout = timeout;
         this.lockMetrics = lockMetrics;
-        this.activeAcquireInterval = lockMetrics.acquireInvoked();
+        this.reentry = reentry;
+        this.activeAcquireInterval = lockMetrics.acquireInvoked(reentry);
     }
 
     public String getThreadName() { return threadLockStats.getThreadName(); }
@@ -101,22 +104,22 @@ public class LockAttempt {
 
     void acquireFailed() {
         setTerminalState(LockState.ACQUIRE_FAILED);
-        lockMetrics.acquireFailed(activeAcquireInterval);
+        lockMetrics.acquireFailed(reentry, activeAcquireInterval);
     }
 
     void timedOut() {
         setTerminalState(LockState.TIMED_OUT);
-        lockMetrics.acquireTimedOut(activeAcquireInterval);
+        lockMetrics.acquireTimedOut(reentry, activeAcquireInterval);
     }
 
     void lockAcquired() {
         lockState = LockState.ACQUIRED;
         lockAcquiredInstant = Optional.of(Instant.now());
-        activeLockedInterval = lockMetrics.lockAcquired(activeAcquireInterval);
+        activeLockedInterval = Optional.of(lockMetrics.lockAcquired(reentry, activeAcquireInterval));
     }
 
     void preRelease() {
-        lockMetrics.preRelease(activeLockedInterval);
+        lockMetrics.preRelease(reentry, activeLockedInterval.orElseThrow());
     }
 
     void postRelease() {
@@ -125,7 +128,7 @@ public class LockAttempt {
 
     void releaseFailed() {
         setTerminalState(LockState.RELEASED_WITH_ERROR);
-        lockMetrics.releaseFailed();
+        lockMetrics.releaseFailed(reentry);
     }
 
     void setTerminalState(LockState terminalState) { setTerminalState(terminalState, Instant.now()); }
diff --git a/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockMetrics.java b/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockMetrics.java
index 18ab70d42da..36758354171 100644
--- a/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockMetrics.java
+++ b/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockMetrics.java
@@ -17,6 +17,7 @@ public class LockMetrics {
     private final AtomicInteger acquireSucceededCount = new AtomicInteger(0);
     private final AtomicInteger releaseCount = new AtomicInteger(0);
     private final AtomicInteger releaseFailedCount = new AtomicInteger(0);
+    private final AtomicInteger reentryCount = new AtomicInteger(0);
 
     private final AtomicInteger cumulativeAcquireCount = new AtomicInteger(0);
     private final AtomicInteger cumulativeAcquireFailedCount = new AtomicInteger(0);
@@ -24,43 +25,55 @@ public class LockMetrics {
     private final AtomicInteger cumulativeAcquireSucceededCount = new AtomicInteger(0);
     private final AtomicInteger cumulativeReleaseCount = new AtomicInteger(0);
     private final AtomicInteger cumulativeReleaseFailedCount = new AtomicInteger(0);
+    private final AtomicInteger cumulativeReentryCount = new AtomicInteger(0);
 
     private final LatencyStats acquireStats = new LatencyStats();
     private final LatencyStats lockedStats = new LatencyStats();
 
     /** Returns a Runnable that must be invoked when the acquire() finishes. */
-    ActiveInterval acquireInvoked() {
+    ActiveInterval acquireInvoked(boolean reentry) {
+        if (reentry) {
+            reentryCount.incrementAndGet();
+            cumulativeReentryCount.incrementAndGet();
+            return () -> { };
+        }
+
         acquireCount.incrementAndGet();
         cumulativeAcquireCount.incrementAndGet();
         return acquireStats.startNewInterval();
     }
 
-    void acquireFailed(ActiveInterval acquireInterval) {
+    void acquireFailed(boolean reentry, ActiveInterval acquireInterval) {
         acquireInterval.close();
+        if (reentry) return;
         acquireFailedCount.incrementAndGet();
         cumulativeAcquireFailedCount.incrementAndGet();
     }
 
-    void acquireTimedOut(ActiveInterval acquireInterval) {
+    void acquireTimedOut(boolean reentry, ActiveInterval acquireInterval) {
         acquireInterval.close();
+        if (reentry) return;
         acquireTimedOutCount.incrementAndGet();
         cumulativeAcquireTimedOutCount.incrementAndGet();
     }
 
-    ActiveInterval lockAcquired(ActiveInterval acquireInterval) {
+    ActiveInterval lockAcquired(boolean reentry, ActiveInterval acquireInterval) {
         acquireInterval.close();
+        if (reentry) return () -> {};
         acquireSucceededCount.incrementAndGet();
         cumulativeAcquireSucceededCount.incrementAndGet();
         return lockedStats.startNewInterval();
     }
 
-    void preRelease(ActiveInterval lockedInterval) {
+    void preRelease(boolean reentry, ActiveInterval lockedInterval) {
         lockedInterval.close();
+        if (reentry) return;
         releaseCount.incrementAndGet();
         cumulativeReleaseCount.incrementAndGet();
     }
 
-    void releaseFailed() {
+    void releaseFailed(boolean reentry) {
+        if (reentry) return;
         releaseFailedCount.incrementAndGet();
         cumulativeReleaseFailedCount.incrementAndGet();
     }
@@ -71,6 +84,7 @@ public class LockMetrics {
     public int getAndResetAcquireSucceededCount() { return acquireSucceededCount.getAndSet(0); }
     public int getAndResetReleaseCount() { return releaseCount.getAndSet(0); }
     public int getAndResetReleaseFailedCount() { return releaseFailedCount.getAndSet(0); }
+    public int getAndResetReentryCount() { return reentryCount.getAndSet(0); }
 
     public int getCumulativeAcquireCount() { return cumulativeAcquireCount.get(); }
     public int getCumulativeAcquireFailedCount() { return cumulativeAcquireFailedCount.get(); }
@@ -78,6 +92,7 @@ public class LockMetrics {
     public int getCumulativeAcquireSucceededCount() { return cumulativeAcquireSucceededCount.get(); }
     public int getCumulativeReleaseCount() { return cumulativeReleaseCount.get(); }
     public int getCumulativeReleaseFailedCount() { return cumulativeReleaseFailedCount.get(); }
+    public int getCumulativeReentryCount() { return cumulativeReentryCount.get(); }
 
     public LatencyMetrics getAcquireLatencyMetrics() { return acquireStats.getLatencyMetrics(); }
     public LatencyMetrics getLockedLatencyMetrics() { return lockedStats.getLatencyMetrics(); }
@@ -86,20 +101,22 @@ public class LockMetrics {
     public LatencyMetrics getAndResetLockedLatencyMetrics() { return lockedStats.getLatencyMetricsAndStartNewPeriod(); }
 
     //  For tests
-    void setAcquireCount(int count) { acquireCount.set(count); }
-    void setAcquireFailedCount(int count) { acquireFailedCount.set(count); }
-    void setAcquireTimedOutCount(int count) { acquireTimedOutCount.set(count); }
-    void setAcquireSucceededCount(int count) { acquireSucceededCount.set(count); }
-    void setReleaseCount(int count) { releaseCount.set(count); }
-    void setReleaseFailedCount(int count) { releaseFailedCount.set(count); }
+    LockMetrics setAcquireCount(int count) { acquireCount.set(count); return this; }
+    LockMetrics setAcquireFailedCount(int count) { acquireFailedCount.set(count); return this; }
+    LockMetrics setAcquireTimedOutCount(int count) { acquireTimedOutCount.set(count); return this; }
+    LockMetrics setAcquireSucceededCount(int count) { acquireSucceededCount.set(count); return this; }
+    LockMetrics setReleaseCount(int count) { releaseCount.set(count); return this; }
+    LockMetrics setReleaseFailedCount(int count) { releaseFailedCount.set(count); return this; }
+    LockMetrics setReentryCount(int count) { reentryCount.set(count); return this; }
 
     //  For tests
-    void setCumulativeAcquireCount(int count) { cumulativeAcquireCount.set(count); }
-    void setCumulativeAcquireFailedCount(int count) { cumulativeAcquireFailedCount.set(count); }
-    void setCumulativeAcquireTimedOutCount(int count) { cumulativeAcquireTimedOutCount.set(count); }
-    void setCumulativeAcquireSucceededCount(int count) { cumulativeAcquireSucceededCount.set(count); }
-    void setCumulativeReleaseCount(int count) { cumulativeReleaseCount.set(count); }
-    void setCumulativeReleaseFailedCount(int count) { cumulativeReleaseFailedCount.set(count); }
+    LockMetrics setCumulativeAcquireCount(int count) { cumulativeAcquireCount.set(count); return this; }
+    LockMetrics setCumulativeAcquireFailedCount(int count) { cumulativeAcquireFailedCount.set(count); return this; }
+    LockMetrics setCumulativeAcquireTimedOutCount(int count) { cumulativeAcquireTimedOutCount.set(count); return this; }
+    LockMetrics setCumulativeAcquireSucceededCount(int count) { cumulativeAcquireSucceededCount.set(count); return this; }
+    LockMetrics setCumulativeReleaseCount(int count) { cumulativeReleaseCount.set(count); return this; }
+    LockMetrics setCumulativeReleaseFailedCount(int count) { cumulativeReleaseFailedCount.set(count); return this; }
+    LockMetrics setCumulativeReentryCount(int count) { cumulativeReentryCount.set(count); return this; }
 
     @Override
     public String toString() {
@@ -110,12 +127,14 @@ public class LockMetrics {
                 ", acquireSucceededCount=" + acquireSucceededCount +
                 ", releaseCount=" + releaseCount +
                 ", releaseFailedCount=" + releaseFailedCount +
+                ", reentryCount=" + reentryCount +
                 ", cumulativeAcquireCount=" + cumulativeAcquireCount +
                 ", cumulativeAcquireFailedCount=" + cumulativeAcquireFailedCount +
                 ", cumulativeAcquireTimedOutCount=" + cumulativeAcquireTimedOutCount +
                 ", cumulativeAcquireSucceededCount=" + cumulativeAcquireSucceededCount +
                 ", cumulativeReleaseCount=" + cumulativeReleaseCount +
                 ", cumulativeReleaseFailedCount=" + cumulativeReleaseFailedCount +
+                ", cumulativeReentryCount=" + cumulativeReentryCount +
                 ", acquireStats=" + acquireStats +
                 ", lockedStats=" + lockedStats +
                 '}';
diff --git a/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/ThreadLockStats.java b/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/ThreadLockStats.java
index 964aa83c52f..393fac5e3db 100644
--- a/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/ThreadLockStats.java
+++ b/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/ThreadLockStats.java
@@ -64,7 +64,10 @@ public class ThreadLockStats {
 
     /** Mutable method (see class doc) */
     public void invokingAcquire(String lockPath, Duration timeout) {
-        LockAttempt lockAttempt = LockAttempt.invokingAcquire(this, lockPath, timeout, getGlobalLockMetrics(lockPath));
+        boolean reentry = lockAttemptsStack.stream().anyMatch(lockAttempt -> lockAttempt.getLockPath().equals(lockPath));
+
+        LockAttempt lockAttempt = LockAttempt.invokingAcquire(this, lockPath, timeout,
+                getGlobalLockMetrics(lockPath), reentry);
 
         LockAttempt lastLockAttempt = lockAttemptsStack.peekLast();
         if (lastLockAttempt == null) {
diff --git a/zkfacade/src/test/java/com/yahoo/vespa/curator/stats/LockAttemptSamplesTest.java b/zkfacade/src/test/java/com/yahoo/vespa/curator/stats/LockAttemptSamplesTest.java
index 252a90f8bb4..e54e340deb5 100644
--- a/zkfacade/src/test/java/com/yahoo/vespa/curator/stats/LockAttemptSamplesTest.java
+++ b/zkfacade/src/test/java/com/yahoo/vespa/curator/stats/LockAttemptSamplesTest.java
@@ -54,7 +54,7 @@ public class LockAttemptSamplesTest {
 
     private boolean maybeSample(String lockPath, int secondsDuration) {
         LockAttempt lockAttempt = LockAttempt.invokingAcquire(threadLockStats, lockPath,
-                Duration.ofSeconds(1), new LockMetrics());
+                Duration.ofSeconds(1), new LockMetrics(), false);
         Instant instant = lockAttempt.getTimeAcquiredWasInvoked().plus(Duration.ofSeconds(secondsDuration));
         lockAttempt.setTerminalState(LockAttempt.LockState.RELEASED, instant);
         return samples.maybeSample(lockAttempt);
diff --git a/zkfacade/src/test/java/com/yahoo/vespa/curator/stats/LockTest.java b/zkfacade/src/test/java/com/yahoo/vespa/curator/stats/LockTest.java
index d673655c798..f440c2cfad8 100644
--- a/zkfacade/src/test/java/com/yahoo/vespa/curator/stats/LockTest.java
+++ b/zkfacade/src/test/java/com/yahoo/vespa/curator/stats/LockTest.java
@@ -26,8 +26,10 @@ import static org.mockito.Mockito.when;
 public class LockTest {
     private final InterProcessLock mutex = mock(InterProcessLock.class);
     private final String lockPath = "/lock/path";
+    private final String lock2Path = "/lock2/path";
     private final Duration acquireTimeout = Duration.ofSeconds(10);
     private final Lock lock = new Lock(lockPath, mutex);
+    private final Lock lock2 = new Lock(lock2Path, mutex);
 
     @Before
     public void setUp() {
@@ -51,7 +53,7 @@ public class LockTest {
         expectedMetrics.setCumulativeAcquireCount(1);
         expectedMetrics.setAcquireFailedCount(1);
         expectedMetrics.setCumulativeAcquireFailedCount(1);
-        assertLockMetrics(expectedMetrics);
+        assertLockMetricsIs(expectedMetrics);
 
         List<LockAttempt> slowLockAttempts = LockStats.getGlobal().getLockAttemptSamples();
         assertEquals(1, slowLockAttempts.size());
@@ -69,8 +71,15 @@ public class LockTest {
         assertEquals(0, threadLockStats.getOngoingLockAttempts().size());
     }
 
-    private void assertLockMetrics(LockMetrics expected) {
-        LockMetrics actual = LockStats.getGlobal().getLockMetricsByPath().get(lockPath);
+    private void assertLock2MetricsIs(LockMetrics expected) {
+        assertLockMetrics(expected, LockStats.getGlobal().getLockMetricsByPath().get(lock2Path));
+    }
+
+    private void assertLockMetricsIs(LockMetrics expected) {
+        assertLockMetrics(expected, LockStats.getGlobal().getLockMetricsByPath().get(lockPath));
+    }
+
+    private void assertLockMetrics(LockMetrics expected, LockMetrics actual) {
         assertNotNull(actual);
 
         assertEquals(expected.getCumulativeAcquireCount(), actual.getCumulativeAcquireCount());
@@ -79,6 +88,7 @@ public class LockTest {
         assertEquals(expected.getCumulativeAcquireSucceededCount(), actual.getCumulativeAcquireSucceededCount());
         assertEquals(expected.getCumulativeReleaseCount(), actual.getCumulativeReleaseCount());
         assertEquals(expected.getCumulativeReleaseFailedCount(), actual.getCumulativeReleaseFailedCount());
+        assertEquals(expected.getCumulativeReentryCount(), actual.getCumulativeReentryCount());
 
         assertEquals(expected.getAndResetAcquireCount(), actual.getAndResetAcquireCount());
         assertEquals(expected.getAndResetAcquireFailedCount(), actual.getAndResetAcquireFailedCount());
@@ -86,6 +96,7 @@ public class LockTest {
         assertEquals(expected.getAndResetAcquireSucceededCount(), actual.getAndResetAcquireSucceededCount());
         assertEquals(expected.getAndResetReleaseCount(), actual.getAndResetReleaseCount());
         assertEquals(expected.getAndResetReleaseFailedCount(), actual.getAndResetReleaseFailedCount());
+        assertEquals(expected.getAndResetReentryCount(), actual.getAndResetReentryCount());
     }
 
     @Test
@@ -104,7 +115,7 @@ public class LockTest {
         expectedMetrics.setCumulativeAcquireCount(1);
         expectedMetrics.setAcquireTimedOutCount(1);
         expectedMetrics.setCumulativeAcquireTimedOutCount(1);
-        assertLockMetrics(expectedMetrics);
+        assertLockMetricsIs(expectedMetrics);
     }
 
     @Test
@@ -112,36 +123,53 @@ public class LockTest {
         when(mutex.acquire(anyLong(), any())).thenReturn(true);
 
         lock.acquire(acquireTimeout);
+        assertLockMetricsIs(new LockMetrics()
+                .setAcquireCount(1)
+                .setCumulativeAcquireCount(1)
+                .setAcquireSucceededCount(1)
+                .setCumulativeAcquireSucceededCount(1));
+
+        // reenter lock
+        {
+            // NB: non-cumulative counters are reset on fetch
+            lock.acquire(acquireTimeout);
+            assertLockMetricsIs(new LockMetrics()
+                    .setReentryCount(1)
+                    .setCumulativeAcquireCount(1)
+                    .setCumulativeAcquireSucceededCount(1)
+                    .setCumulativeReentryCount(1));
+
+            lock.close();
+            assertLockMetricsIs(new LockMetrics()
+                    .setCumulativeAcquireCount(1)
+                    .setCumulativeAcquireSucceededCount(1)
+                    .setCumulativeReentryCount(1));
+        }
 
-        var expectedMetrics = new LockMetrics();
-        expectedMetrics.setAcquireCount(1);
-        expectedMetrics.setCumulativeAcquireCount(1);
-        expectedMetrics.setAcquireSucceededCount(1);
-        expectedMetrics.setCumulativeAcquireSucceededCount(1);
-        assertLockMetrics(expectedMetrics);
-
-        // reenter
-        // NB: non-cumulative counters are reset on fetch
-        lock.acquire(acquireTimeout);
-        expectedMetrics.setAcquireCount(1);  // reset to 0 above, + 1
-        expectedMetrics.setCumulativeAcquireCount(2);
-        expectedMetrics.setAcquireSucceededCount(1); // reset to 0 above, +1
-        expectedMetrics.setCumulativeAcquireSucceededCount(2);
-        assertLockMetrics(expectedMetrics);
-
-        // inner-most closes
-        lock.close();
-        expectedMetrics.setAcquireCount(0);  // reset to 0 above
-        expectedMetrics.setAcquireSucceededCount(0); // reset to 0 above
-        expectedMetrics.setReleaseCount(1);
-        expectedMetrics.setCumulativeReleaseCount(1);
-        assertLockMetrics(expectedMetrics);
+        // nested lock2
+        {
+            lock2.acquire(acquireTimeout);
+            assertLock2MetricsIs(new LockMetrics()
+                    .setAcquireCount(1)
+                    .setCumulativeAcquireCount(1)
+                    .setAcquireSucceededCount(1)
+                    .setCumulativeAcquireSucceededCount(1));
+
+            lock2.close();
+            assertLock2MetricsIs(new LockMetrics()
+                    .setReleaseCount(1)
+                    .setCumulativeAcquireCount(1)
+                    .setCumulativeAcquireSucceededCount(1)
+                    .setCumulativeReleaseCount(1));
+        }
 
-        // outer-most closes
         lock.close();
-        expectedMetrics.setReleaseCount(1);  // reset to 0 above, +1
-        expectedMetrics.setCumulativeReleaseCount(2);
-        assertLockMetrics(expectedMetrics);
+        assertLockMetricsIs(new LockMetrics()
+                .setReleaseCount(1)
+                .setCumulativeAcquireCount(1)
+                .setCumulativeAcquireSucceededCount(1)
+                .setCumulativeReentryCount(1)
+                .setCumulativeReleaseCount(1));
     }
 
     @Test