From dc66caea51baa3a06381784fcafb1cce9ff6384d Mon Sep 17 00:00:00 2001 From: Håkon Hallingstad Date: Wed, 27 Apr 2022 09:49:25 +0200 Subject: More debug info on controller lock warnings --- .../src/main/java/com/yahoo/vespa/curator/Lock.java | 17 +++++++++-------- .../java/com/yahoo/vespa/curator/stats/LockStats.java | 15 +++++---------- .../com/yahoo/vespa/curator/stats/ThreadLockStats.java | 10 ++++------ 3 files changed, 18 insertions(+), 24 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 05294a5435b..469b8d1355c 100644 --- a/zkfacade/src/main/java/com/yahoo/vespa/curator/Lock.java +++ b/zkfacade/src/main/java/com/yahoo/vespa/curator/Lock.java @@ -9,9 +9,11 @@ import com.yahoo.vespa.curator.stats.ThreadLockStats; import org.apache.curator.framework.recipes.locks.InterProcessLock; import java.time.Duration; +import java.time.Instant; import java.util.HashMap; import java.util.Map; import java.util.concurrent.TimeUnit; +import java.util.function.Consumer; /** * A cluster-wide re-entrant mutex which is released on (the last symmetric) close. @@ -23,9 +25,11 @@ import java.util.concurrent.TimeUnit; */ public class Lock implements Mutex { + // TODO(hakon): Remove once debugging is done private final Object monitor = new Object(); private long nextSequenceNumber = 0; private final Map reentriesByThreadId = new HashMap<>(); + private final Instant created = Instant.now(); private final InterProcessLock mutex; private final String lockPath; @@ -62,13 +66,8 @@ public class Lock implements Mutex { invoke(+1L, threadLockStats::lockAcquired); } - @FunctionalInterface - private interface TriConsumer { - void accept(String lockId, long reentryCountDiff, Map reentriesByThreadId); - } - // TODO(hakon): Remove once debugging is unnecessary - private void invoke(long reentryCountDiff, TriConsumer consumer) { + private void invoke(long reentryCountDiff, Consumer consumer) { long threadId = Thread.currentThread().getId(); final long sequenceNumber; final Map reentriesByThreadIdCopy; @@ -86,8 +85,10 @@ public class Lock implements Mutex { reentriesByThreadIdCopy = Map.copyOf(reentriesByThreadId); } - String lockId = Integer.toHexString(System.identityHashCode(this)); - consumer.accept(lockId, sequenceNumber, reentriesByThreadIdCopy); + String debug = "thread " + threadId + " " + lockPath + "@" + created + " 0x" + + Integer.toHexString(System.identityHashCode(this)) + " #" + sequenceNumber + + ", reentries by thread ID = " + reentriesByThreadIdCopy; + consumer.accept(debug); } @Override diff --git a/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockStats.java b/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockStats.java index ecb344dedb9..a37034b7547 100644 --- a/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockStats.java +++ b/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockStats.java @@ -64,33 +64,28 @@ public class LockStats { } /** Must be invoked only after the first and non-reentry acquisition of the lock. */ - void notifyOfThreadHoldingLock(Thread currentThread, String lockPath, String lockId, - long sequenceNumber, Map reentriesByThreadId) { + void notifyOfThreadHoldingLock(Thread currentThread, String lockPath, String debug) { Thread oldThread = lockPathsHeld.put(lockPath, currentThread); if (oldThread != null) { getLockMetrics(lockPath).incrementAcquireWithoutReleaseCount(); logger.warning("Thread " + currentThread.getName() + " reports it has the lock on " + lockPath + ", but thread " + oldThread.getName() + - " has not reported it released the lock. " + lockId + "#" + sequenceNumber + - ", reentries by thread ID = " + reentriesByThreadId); + " has not reported it released the lock. " + debug); } } /** Must be invoked only before the last and non-reentry release of the lock. */ - void notifyOfThreadReleasingLock(Thread currentThread, String lockPath, String lockId, - long sequenceNumber, Map reentriesByThreadId) { + void notifyOfThreadReleasingLock(Thread currentThread, String lockPath, String debug) { Thread oldThread = lockPathsHeld.remove(lockPath); if (oldThread == null) { getLockMetrics(lockPath).incrementNakedReleaseCount(); logger.warning("Thread " + currentThread.getName() + " is releasing the lock " + lockPath + - ", but nobody owns that lock. " + lockId + "#" + sequenceNumber + - ", reentries by thread ID = " + reentriesByThreadId); + ", but nobody owns that lock. " + debug); } else if (oldThread != currentThread) { getLockMetrics(lockPath).incrementForeignReleaseCount(); logger.warning("Thread " + currentThread.getName() + " is releasing the lock " + lockPath + ", but it was owned by thread " + - oldThread.getName() + ". " + lockId + "#" + sequenceNumber + - ", reentries by thread ID = " + reentriesByThreadId); + oldThread.getName() + ". " + debug); } } 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 7f8eafdcf7f..beda7eaa142 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 @@ -98,7 +98,7 @@ public class ThreadLockStats { } /** Mutable method (see class doc) */ - public void lockAcquired(String lockId, long sequenceNumber, Map reentriesByThreadId) { + public void lockAcquired(String debug) { withLastLockAttempt(lockAttempt -> { // Note on the order of lockAcquired() vs notifyOfThreadHoldingLock(): When the latter is // invoked, other threads may query e.g. isAcquired() on the lockAttempt, which would @@ -107,20 +107,18 @@ public class ThreadLockStats { lockAttempt.lockAcquired(); if (!lockAttempt.isReentry()) { - LockStats.getGlobal().notifyOfThreadHoldingLock(thread, lockAttempt.getLockPath(), - lockId, sequenceNumber, reentriesByThreadId); + LockStats.getGlobal().notifyOfThreadHoldingLock(thread, lockAttempt.getLockPath(), debug); } }); } /** Mutable method (see class doc) */ - public void preRelease(String lockId, long sequenceNumber, Map reentriesByThreadId) { + public void preRelease(String debug) { withLastLockAttempt(lockAttempt -> { // Note on the order of these two statement: Same concerns apply here as in lockAcquired(). if (!lockAttempt.isReentry()) { - LockStats.getGlobal().notifyOfThreadReleasingLock(thread, lockAttempt.getLockPath(), - lockId, sequenceNumber, reentriesByThreadId); + LockStats.getGlobal().notifyOfThreadReleasingLock(thread, lockAttempt.getLockPath(), debug); } lockAttempt.preRelease(); -- cgit v1.2.3