Adds method name to stack trace and adds timeout count and test

5 files changed, 163 insertions, 4 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 7fb6b88cf99..9af83223ae6 100644
--- a/zkfacade/src/main/java/com/yahoo/vespa/curator/Lock.java
+++ b/zkfacade/src/main/java/com/yahoo/vespa/curator/Lock.java
@@ -24,8 +24,13 @@ public class Lock implements Mutex {
     private final String lockPath;
 
     public Lock(String lockPath, Curator curator) {
+        this(lockPath, curator.createMutex(lockPath));
+    }
+
+    /** Public for testing only */
+    public Lock(String lockPath, InterProcessLock mutex) {
         this.lockPath = lockPath;
-        mutex = curator.createMutex(lockPath);
+        this.mutex = mutex;
     }
 
     /** Take the lock with the given timeout. This may be called multiple times from the same thread - each matched by a close */
diff --git a/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockCounters.java b/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockCounters.java
index 4d1b48ef7f3..5309bf755d7 100644
--- a/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockCounters.java
+++ b/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockCounters.java
@@ -1,6 +1,7 @@
 // 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 java.util.Objects;
 import java.util.concurrent.atomic.AtomicInteger;
 
 /**
@@ -27,4 +28,38 @@ public class LockCounters {
     public int locksReleasedCount() { return locksReleasedCount.get(); }
     public int noLocksErrorCount() { return noLocksErrorCount.get(); }
     public int timeoutOnReentrancyErrorCount() { return timeoutOnReentrancyErrorCount.get(); }
+
+    @Override
+    public String toString() {
+        return "LockCounters{" +
+                "invokeAcquireCount=" + invokeAcquireCount +
+                ", inCriticalRegionCount=" + inCriticalRegionCount +
+                ", acquireFailedCount=" + acquireFailedCount +
+                ", acquireTimedOutCount=" + acquireTimedOutCount +
+                ", lockAcquiredCount=" + lockAcquiredCount +
+                ", locksReleasedCount=" + locksReleasedCount +
+                ", noLocksErrorCount=" + noLocksErrorCount +
+                ", timeoutOnReentrancyErrorCount=" + timeoutOnReentrancyErrorCount +
+                '}';
+    }
+
+    @Override
+    public boolean equals(Object o) {
+        if (this == o) return true;
+        if (o == null || getClass() != o.getClass()) return false;
+        LockCounters that = (LockCounters) o;
+        return invokeAcquireCount.get() ==  that.invokeAcquireCount.get() &&
+                inCriticalRegionCount.get() == that.inCriticalRegionCount.get() &&
+                acquireFailedCount.get() == that.acquireFailedCount.get() &&
+                acquireTimedOutCount.get() == that.acquireTimedOutCount.get() &&
+                lockAcquiredCount.get() == that.lockAcquiredCount.get() &&
+                locksReleasedCount.get() == that.locksReleasedCount.get() &&
+                noLocksErrorCount.get() == that.noLocksErrorCount.get() &&
+                timeoutOnReentrancyErrorCount.get() == that.timeoutOnReentrancyErrorCount.get();
+    }
+
+    @Override
+    public int hashCode() {
+        return Objects.hash(invokeAcquireCount, inCriticalRegionCount, acquireFailedCount, acquireTimedOutCount, lockAcquiredCount, locksReleasedCount, noLocksErrorCount, timeoutOnReentrancyErrorCount);
+    }
 }
diff --git a/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockInfo.java b/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockInfo.java
index 1e46b1cf668..e959dae2a93 100644
--- a/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockInfo.java
+++ b/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockInfo.java
@@ -78,8 +78,6 @@ public class LockInfo {
         // This method is public. If invoked concurrently, the this.stackTrace may be updated twice,
         // which is fine.
 
-        if (this.stackTrace.isPresent()) return;
-
         var stackTrace = new StringBuilder();
 
         StackTraceElement[] elements = thread.getStackTrace();
@@ -87,6 +85,8 @@ public class LockInfo {
         for (int i = 0; i < elements.length; ++i) {
             var element = elements[i];
             stackTrace.append(element.getClassName())
+                      .append('.')
+                      .append(element.getMethodName())
                       .append('(')
                       .append(element.getFileName())
                       .append(':')
diff --git a/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/ThreadLockInfo.java b/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/ThreadLockInfo.java
index 9f92b6444be..1e46a153164 100644
--- a/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/ThreadLockInfo.java
+++ b/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/ThreadLockInfo.java
@@ -61,6 +61,12 @@ public class ThreadLockInfo {
                 });
     }
 
+    static void clearStaticDataForTesting() {
+        locks.clear();
+        completedLockInfos.clear();
+        countersByLockPath.clear();
+    }
+
     ThreadLockInfo(Thread currentThread, String lockPath, LockCounters lockCountersForPath) {
         this.thread = currentThread;
         this.lockPath = lockPath;
@@ -89,7 +95,7 @@ public class ThreadLockInfo {
             lockCountersForPath.timeoutOnReentrancyErrorCount.incrementAndGet();
         }
 
-        removeLastLockInfo(lockCountersForPath.timeoutOnReentrancyErrorCount, LockInfo::timedOut);
+        removeLastLockInfo(lockCountersForPath.acquireTimedOutCount, LockInfo::timedOut);
     }
 
     /** Mutable method (see class doc) */
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
new file mode 100644
index 00000000000..23b603eca5c
--- /dev/null
+++ b/zkfacade/src/test/java/com/yahoo/vespa/curator/stats/LockTest.java
@@ -0,0 +1,113 @@
+package com.yahoo.vespa.curator.stats;// Copyright Verizon Media. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
+
+import com.yahoo.vespa.curator.Lock;
+import org.apache.curator.framework.recipes.locks.InterProcessLock;
+import org.junit.Before;
+import org.junit.Test;
+
+import java.time.Duration;
+import java.util.List;
+import java.util.Map;
+import java.util.Optional;
+
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertSame;
+import static org.junit.Assert.assertTrue;
+import static org.junit.Assert.fail;
+import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.ArgumentMatchers.anyLong;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.when;
+
+public class LockTest {
+    private final InterProcessLock mutex = mock(InterProcessLock.class);
+    private final String lockPath = "/lock/path";
+    private final Duration acquireTimeout = Duration.ofSeconds(10);
+    private final Lock lock = new Lock(lockPath, mutex);
+
+    @Before
+    public void setUp() {
+        ThreadLockInfo.clearStaticDataForTesting();
+    }
+
+    @Test
+    public void acquireThrows() throws Exception {
+        Exception exception = new Exception("example curator exception");
+        when(mutex.acquire(anyLong(), any())).thenThrow(exception);
+
+        try {
+            lock.acquire(acquireTimeout);
+            fail();
+        } catch (Exception e) {
+            assertSame(e.getCause(), exception);
+        }
+
+        var expectedCounters = new LockCounters();
+        expectedCounters.invokeAcquireCount.set(1);
+        expectedCounters.acquireFailedCount.set(1);
+        assertEquals(Map.of(lockPath, expectedCounters), ThreadLockInfo.getLockCountersByPath());
+
+        List<LockInfo> slowLockInfos = ThreadLockInfo.getSlowLockInfos();
+        assertEquals(1, slowLockInfos.size());
+        LockInfo slowLockInfo = slowLockInfos.get(0);
+        assertEquals(acquireTimeout, slowLockInfo.getAcquireTimeout());
+        Optional<String> stackTrace = slowLockInfo.getStackTrace();
+        assertTrue(stackTrace.isPresent());
+        assertTrue("bad stacktrace: " + stackTrace.get(), stackTrace.get().contains(".Lock.acquire(Lock.java"));
+        assertEquals(LockInfo.LockState.ACQUIRE_FAILED, slowLockInfo.getLockState());
+        assertTrue(slowLockInfo.getTimeTerminalStateWasReached().isPresent());
+
+        List<ThreadLockInfo> threadLockInfos = ThreadLockInfo.getThreadLockInfos();
+        assertEquals(1, threadLockInfos.size());
+        ThreadLockInfo threadLockInfo = threadLockInfos.get(0);
+        assertEquals(0, threadLockInfo.getLockInfos().size());
+    }
+
+    @Test
+    public void acquireTimesOut() throws Exception {
+        when(mutex.acquire(anyLong(), any())).thenReturn(false);
+
+        try {
+            lock.acquire(acquireTimeout);
+            fail();
+        } catch (Exception e) {
+            assertTrue("unexpected exception: " + e.getMessage(), e.getMessage().contains("Timed out"));
+        }
+
+        var expectedCounters = new LockCounters();
+        expectedCounters.invokeAcquireCount.set(1);
+        expectedCounters.acquireTimedOutCount.set(1);
+        assertEquals(Map.of(lockPath, expectedCounters), ThreadLockInfo.getLockCountersByPath());
+    }
+
+    @Test
+    public void acquired() throws Exception {
+        when(mutex.acquire(anyLong(), any())).thenReturn(true);
+
+        lock.acquire(acquireTimeout);
+
+        var expectedCounters = new LockCounters();
+        expectedCounters.invokeAcquireCount.set(1);
+        expectedCounters.lockAcquiredCount.set(1);
+        expectedCounters.inCriticalRegionCount.set(1);
+        assertEquals(Map.of(lockPath, expectedCounters), ThreadLockInfo.getLockCountersByPath());
+
+        // reenter
+        lock.acquire(acquireTimeout);
+        expectedCounters.invokeAcquireCount.set(2);
+        expectedCounters.lockAcquiredCount.set(2);
+        expectedCounters.inCriticalRegionCount.set(2);
+
+        // inner-most closes
+        lock.close();
+        expectedCounters.inCriticalRegionCount.set(1);
+        expectedCounters.locksReleasedCount.set(1);
+        assertEquals(Map.of(lockPath, expectedCounters), ThreadLockInfo.getLockCountersByPath());
+
+        // outer-most closes
+        lock.close();
+        expectedCounters.inCriticalRegionCount.set(0);
+        expectedCounters.locksReleasedCount.set(2);
+        assertEquals(Map.of(lockPath, expectedCounters), ThreadLockInfo.getLockCountersByPath());
+    }
+}