From c96ab458bc2bf11ab94e1236c16785592f43f2c1 Mon Sep 17 00:00:00 2001
From: Håkon Hallingstad <hakon@verizonmedia.com>
Date: Wed, 7 Oct 2020 13:00:46 +0200
Subject: Avoid even small double-counting of locked time

---
 .../main/java/com/yahoo/vespa/curator/Lock.java    |  7 ++++--
 .../com/yahoo/vespa/curator/stats/LockAttempt.java | 11 +++++---
 .../com/yahoo/vespa/curator/stats/LockMetrics.java | 15 +++++------
 .../yahoo/vespa/curator/stats/ThreadLockStats.java | 29 ++++++++++++++--------
 4 files changed, 39 insertions(+), 23 deletions(-)

diff --git a/zkfacade/src/main/java/com/yahoo/vespa/curator/Lock.java b/zkfacade/src/main/java/com/yahoo/vespa/curator/Lock.java
index 451389694c6..6c96748f92b 100644
--- a/zkfacade/src/main/java/com/yahoo/vespa/curator/Lock.java
+++ b/zkfacade/src/main/java/com/yahoo/vespa/curator/Lock.java
@@ -57,12 +57,15 @@ public class Lock implements Mutex {
 
     @Override
     public void close() {
+        ThreadLockStats threadLockStats = LockStats.getForCurrentThread();
+        // Update metrics now before release() to avoid double-counting time in locked state.
+        threadLockStats.preRelease();
         try {
             mutex.release();
-            LockStats.getForCurrentThread().lockReleased();
+            threadLockStats.postRelease();
         }
         catch (Exception e) {
-            LockStats.getForCurrentThread().lockReleaseFailed();
+            threadLockStats.releaseFailed();
             throw new RuntimeException("Exception releasing lock '" + lockPath + "'");
         }
     }
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 3a62c7bf988..1478b36d331 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
@@ -115,14 +115,17 @@ public class LockAttempt {
         activeLockedInterval = lockMetrics.lockAcquired(activeAcquireInterval);
     }
 
-    void released() {
+    void preRelease() {
+        lockMetrics.preRelease(activeLockedInterval);
+    }
+
+    void postRelease() {
         setTerminalState(LockState.RELEASED);
-        lockMetrics.release(activeLockedInterval);
     }
 
-    void releasedWithError() {
+    void releaseFailed() {
         setTerminalState(LockState.RELEASED_WITH_ERROR);
-        lockMetrics.releaseFailed(activeLockedInterval);
+        lockMetrics.releaseFailed();
     }
 
     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 51dcf3dd8de..18ab70d42da 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
@@ -1,6 +1,8 @@
 // Copyright Verizon Media. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
 package com.yahoo.vespa.curator.stats;
 
+import com.yahoo.vespa.curator.stats.LatencyStats.ActiveInterval;
+
 import java.util.concurrent.atomic.AtomicInteger;
 
 /**
@@ -27,39 +29,38 @@ public class LockMetrics {
     private final LatencyStats lockedStats = new LatencyStats();
 
     /** Returns a Runnable that must be invoked when the acquire() finishes. */
-    LatencyStats.ActiveInterval acquireInvoked() {
+    ActiveInterval acquireInvoked() {
         acquireCount.incrementAndGet();
         cumulativeAcquireCount.incrementAndGet();
         return acquireStats.startNewInterval();
     }
 
-    void acquireFailed(LatencyStats.ActiveInterval acquireInterval) {
+    void acquireFailed(ActiveInterval acquireInterval) {
         acquireInterval.close();
         acquireFailedCount.incrementAndGet();
         cumulativeAcquireFailedCount.incrementAndGet();
     }
 
-    void acquireTimedOut(LatencyStats.ActiveInterval acquireInterval) {
+    void acquireTimedOut(ActiveInterval acquireInterval) {
         acquireInterval.close();
         acquireTimedOutCount.incrementAndGet();
         cumulativeAcquireTimedOutCount.incrementAndGet();
     }
 
-    LatencyStats.ActiveInterval lockAcquired(LatencyStats.ActiveInterval acquireInterval) {
+    ActiveInterval lockAcquired(ActiveInterval acquireInterval) {
         acquireInterval.close();
         acquireSucceededCount.incrementAndGet();
         cumulativeAcquireSucceededCount.incrementAndGet();
         return lockedStats.startNewInterval();
     }
 
-    void release(LatencyStats.ActiveInterval lockedInterval) {
+    void preRelease(ActiveInterval lockedInterval) {
         lockedInterval.close();
         releaseCount.incrementAndGet();
         cumulativeReleaseCount.incrementAndGet();
     }
 
-    void releaseFailed(LatencyStats.ActiveInterval lockedInterval) {
-        release(lockedInterval);
+    void releaseFailed() {
         releaseFailedCount.incrementAndGet();
         cumulativeReleaseFailedCount.incrementAndGet();
     }
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 cd6ae3b1e68..964aa83c52f 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
@@ -87,23 +87,22 @@ public class ThreadLockStats {
 
     /** Mutable method (see class doc) */
     public void lockAcquired() {
-        LockAttempt lockAttempt = lockAttemptsStack.peekLast();
-        if (lockAttempt == null) {
-            logger.warning("Unable to get last lock attempt as the lock attempt stack is empty");
-            return;
-        }
+        withLastLockAttempt(LockAttempt::lockAcquired);
+    }
 
-        lockAttempt.lockAcquired();
+    /** Mutable method (see class doc) */
+    public void preRelease() {
+        withLastLockAttempt(LockAttempt::preRelease);
     }
 
     /** Mutable method (see class doc) */
-    public void lockReleased() {
-        removeLastLockAttempt(LockAttempt::released);
+    public void postRelease() {
+        removeLastLockAttempt(LockAttempt::postRelease);
     }
 
     /** Mutable method (see class doc) */
-    public void lockReleaseFailed() {
-        removeLastLockAttempt(LockAttempt::releasedWithError);
+    public void releaseFailed() {
+        removeLastLockAttempt(LockAttempt::releaseFailed);
     }
 
     /** Mutable method (see class doc) */
@@ -127,6 +126,16 @@ public class ThreadLockStats {
         return LockStats.getGlobal().getLockMetrics(lockPath);
     }
 
+    private void withLastLockAttempt(Consumer<LockAttempt> lockAttemptConsumer) {
+        LockAttempt lockAttempt = lockAttemptsStack.peekLast();
+        if (lockAttempt == null) {
+            logger.warning("Unable to get last lock attempt as the lock attempt stack is empty");
+            return;
+        }
+
+        lockAttemptConsumer.accept(lockAttempt);
+    }
+
     private void removeLastLockAttempt(Consumer<LockAttempt> completeLockAttempt) {
         LockAttempt lockAttempt = lockAttemptsStack.pollLast();
         if (lockAttempt == null) {
-- 
cgit v1.2.3