Also show the longest-living historical locks, with stack trace

2 files changed, 59 insertions, 11 deletions

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 b192210c3de..6e58c1ea81b 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
@@ -4,6 +4,7 @@ package com.yahoo.vespa.curator.stats;
 import java.time.Duration;
 import java.time.Instant;
 import java.util.Optional;
+import java.util.stream.Stream;
 
 /**
  * Information about a lock.
@@ -14,15 +15,18 @@ import java.util.Optional;
  */
 public class LockInfo {
 
+    private final String threadName;
+    private final String lockPath;
     private final int threadHoldCountOnAcquire;
     private final Instant acquireInstant;
     private final Duration timeout;
 
     private volatile Optional<Instant> lockAcquiredInstant = Optional.empty();
     private volatile Optional<Instant> terminalStateInstant = Optional.empty();
+    private volatile Optional<String> stackTrace = Optional.empty();
 
-    public static LockInfo invokingAcquire(int holdCount, Duration timeout) {
-        return new LockInfo(holdCount, timeout);
+    public static LockInfo invokingAcquire(String threadName, String lockPath, int holdCount, Duration timeout) {
+        return new LockInfo(threadName, lockPath, holdCount, timeout);
     }
 
     public enum LockState {
@@ -37,18 +41,28 @@ public class LockInfo {
 
     private volatile LockState lockState = LockState.ACQUIRING;
 
-    private LockInfo(int threadHoldCountOnAcquire, Duration timeout) {
+    private LockInfo(String threadName, String lockPath, int threadHoldCountOnAcquire, Duration timeout) {
+        this.threadName = threadName;
+        this.lockPath = lockPath;
         this.threadHoldCountOnAcquire = threadHoldCountOnAcquire;
         this.acquireInstant = Instant.now();
         this.timeout = timeout;
     }
 
+    public String getThreadName() { return threadName; }
+    public String getLockPath() { return lockPath; }
     public int getThreadHoldCountOnAcquire() { return threadHoldCountOnAcquire; }
     public Instant getTimeAcquiredWasInvoked() { return acquireInstant; }
     public Duration getAcquireTimeout() { return timeout; }
     public LockState getLockState() { return lockState; }
     public Optional<Instant> getTimeLockWasAcquired() { return lockAcquiredInstant; }
     public Optional<Instant> getTimeTerminalStateWasReached() { return terminalStateInstant; }
+    public Optional<String> getStackTrace() { return stackTrace; }
+
+    /** Get time from just before trying to acquire lock to the time the terminal state was reached, or ZERO. */
+    public Duration getTotalTime() {
+        return terminalStateInstant.map(instant -> Duration.between(acquireInstant, instant)).orElse(Duration.ZERO);
+    }
 
     void timedOut() { setTerminalState(LockState.TIMED_OUT); }
     void failedToAcquireReentrantLock() { setTerminalState(LockState.FAILED_TO_REENTER); }
@@ -63,4 +77,24 @@ public class LockInfo {
         lockState = terminalState;
         terminalStateInstant = Optional.of(Instant.now());
     }
+
+    /** Fill in the stack trace starting at the caller's stack frame. */
+    void fillStackTrace() {
+        final int elementsToIgnore = 1;
+
+        var stackTrace = new StringBuilder();
+
+        StackTraceElement[] elements = Thread.currentThread().getStackTrace();
+        for (int i = elementsToIgnore; i < elements.length; ++i) {
+            Stream.of(elements).forEach(element ->
+                    stackTrace.append(element.getClassName())
+                            .append('(')
+                            .append(element.getFileName())
+                            .append(':')
+                            .append(element.getLineNumber())
+                            .append(")\n"));
+        }
+
+        this.stackTrace = Optional.of(stackTrace.toString());
+    }
 }
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 bba39e6dc49..5e77ec76290 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
@@ -4,11 +4,12 @@ package com.yahoo.vespa.curator.stats;
 import com.yahoo.vespa.curator.Lock;
 
 import java.time.Duration;
+import java.util.Comparator;
 import java.util.List;
 import java.util.Map;
 import java.util.Optional;
+import java.util.PriorityQueue;
 import java.util.concurrent.ConcurrentHashMap;
-import java.util.concurrent.ConcurrentLinkedDeque;
 import java.util.concurrent.ConcurrentLinkedQueue;
 import java.util.concurrent.atomic.AtomicInteger;
 import java.util.concurrent.locks.ReentrantLock;
@@ -26,8 +27,10 @@ public class ThreadLockInfo {
 
     private static final ConcurrentHashMap<Thread, ThreadLockInfo> locks = new ConcurrentHashMap<>();
 
-    private static final int MAX_COMPLETED_LOCK_INFOS_SIZE = 10;
-    private static final ConcurrentLinkedDeque<LockInfo> completedLockInfos = new ConcurrentLinkedDeque<>();
+    private static final int MAX_COMPLETED_LOCK_INFOS_SIZE = 5;
+    /** Would have used a thread-safe priority queue. */
+    private static final Object completedLockInfosMonitor = new Object();
+    private static final PriorityQueue<LockInfo> completedLockInfos = new PriorityQueue<>(Comparator.comparing(LockInfo::getTotalTime));
 
     private static final ConcurrentHashMap<String, LockCounters> countersByLockPath = new ConcurrentHashMap<>();
 
@@ -43,6 +46,12 @@ public class ThreadLockInfo {
 
     public static List<ThreadLockInfo> getThreadLockInfos() { return List.copyOf(locks.values()); }
 
+    public static List<LockInfo> getSlowLockInfos() {
+        synchronized (completedLockInfosMonitor) {
+            return List.copyOf(completedLockInfos);
+        }
+    }
+
     /** Returns the per-thread singleton ThreadLockInfo. */
     public static ThreadLockInfo getCurrentThreadLockInfo(String lockPath, ReentrantLock lock) {
         return locks.computeIfAbsent(
@@ -68,7 +77,7 @@ public class ThreadLockInfo {
     public void invokingAcquire(Duration timeout) {
         lockCountersForPath.invokeAcquireCount.incrementAndGet();
         lockCountersForPath.inCriticalRegionCount.incrementAndGet();
-        lockInfos.add(LockInfo.invokingAcquire(lock.getHoldCount(), timeout));
+        lockInfos.add(LockInfo.invokingAcquire(getThreadName(), lockPath, lock.getHoldCount(), timeout));
     }
 
     /** Mutable method (see class doc) */
@@ -113,10 +122,15 @@ public class ThreadLockInfo {
         LockInfo lockInfo = lockInfos.poll();
         completeLockInfo.accept(lockInfo);
 
-        if (completedLockInfos.size() >= MAX_COMPLETED_LOCK_INFOS_SIZE) {
-            // This is thread-safe, as no-one but currentThread mutates completedLockInfos
-            completedLockInfos.removeLast();
+        synchronized (completedLockInfosMonitor) {
+            if (completedLockInfos.size() < MAX_COMPLETED_LOCK_INFOS_SIZE) {
+                lockInfo.fillStackTrace();
+                completedLockInfos.add(lockInfo);
+            } else if (lockInfo.getTotalTime().compareTo(completedLockInfos.peek().getTotalTime()) > 0) {
+                completedLockInfos.poll();
+                lockInfo.fillStackTrace();
+                completedLockInfos.add(lockInfo);
+            }
         }
-        completedLockInfos.addFirst(lockInfo);
     }
 }