[Minor] Extended DefaultLockHandler to log owner of locks on lock timeout

This commit is contained in:
Robert von Burg 2023-02-14 09:13:10 +01:00
parent 0dacd040c0
commit 2f1923218b
Signed by: eitch
GPG Key ID: 75DB9C85C74331F7
1 changed files with 52 additions and 36 deletions

View File

@ -16,6 +16,7 @@
package li.strolch.agent.impl; package li.strolch.agent.impl;
import java.text.MessageFormat; import java.text.MessageFormat;
import java.util.Collection;
import java.util.HashMap; import java.util.HashMap;
import java.util.Map; import java.util.Map;
import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.ConcurrentHashMap;
@ -43,15 +44,15 @@ public class DefaultLockHandler implements LockHandler {
private final String realm; private final String realm;
private final TimeUnit tryLockTimeUnit; private final TimeUnit tryLockTimeUnit;
private final long tryLockTime; private final long tryLockTime;
private final Map<Locator, TypedTuple<ReentrantLock, Long>> lockMap; private final Map<Locator, TypedTuple<Lock, Long>> lockMap;
private ScheduledFuture<?> cleanupTask; private ScheduledFuture<?> cleanupTask;
public DefaultLockHandler(StrolchAgent agent, String realm, TimeUnit tryLockTimeUnit, long tryLockTime) { public DefaultLockHandler(StrolchAgent agent, String realm, TimeUnit tryLockTimeUnit, long tryLockTime) {
DBC.PRE.assertNotNull("agent must be set!", agent); //$NON-NLS-1$ DBC.PRE.assertNotNull("agent must be set!", agent);
DBC.PRE.assertNotEmpty("Realm must be set!", realm); //$NON-NLS-1$ DBC.PRE.assertNotEmpty("Realm must be set!", realm);
DBC.PRE.assertNotNull("TimeUnit must be set!", tryLockTimeUnit); //$NON-NLS-1$ DBC.PRE.assertNotNull("TimeUnit must be set!", tryLockTimeUnit);
DBC.PRE.assertNotEquals("try lock time must not be 0", 0, tryLockTime); //$NON-NLS-1$ DBC.PRE.assertNotEquals("try lock time must not be 0", 0, tryLockTime);
this.agent = agent; this.agent = agent;
this.realm = realm; this.realm = realm;
@ -74,14 +75,14 @@ public class DefaultLockHandler implements LockHandler {
private void cleanupOldLocks() { private void cleanupOldLocks() {
Map<Locator, TypedTuple<ReentrantLock, Long>> lockMap; Map<Locator, TypedTuple<Lock, Long>> lockMap;
synchronized (this.lockMap) { synchronized (this.lockMap) {
lockMap = new HashMap<>(this.lockMap); lockMap = new HashMap<>(this.lockMap);
} }
long maxAge = System.currentTimeMillis() - TimeUnit.HOURS.toMillis(1); long maxAge = System.currentTimeMillis() - TimeUnit.HOURS.toMillis(1);
long count = 0; long count = 0;
for (Map.Entry<Locator, TypedTuple<ReentrantLock, Long>> entry : lockMap.entrySet()) { for (Map.Entry<Locator, TypedTuple<Lock, Long>> entry : lockMap.entrySet()) {
if (!entry.getValue().getFirst().isLocked() && entry.getValue().getSecond() <= maxAge) { if (!entry.getValue().getFirst().isLocked() && entry.getValue().getSecond() <= maxAge) {
this.lockMap.remove(entry.getKey()); this.lockMap.remove(entry.getKey());
count++; count++;
@ -97,27 +98,26 @@ public class DefaultLockHandler implements LockHandler {
@Override @Override
public void lock(Locator locator) throws StrolchLockException { public void lock(Locator locator) throws StrolchLockException {
TypedTuple<ReentrantLock, Long> tuple = this.lockMap.computeIfAbsent(locator, TypedTuple<Lock, Long> tuple = this.lockMap.computeIfAbsent(locator,
l -> new TypedTuple<>(new ReentrantLock(true), System.currentTimeMillis())); l -> new TypedTuple<>(new Lock(true), System.currentTimeMillis()));
lock(this.tryLockTimeUnit, this.tryLockTime, tuple, locator); lock(this.tryLockTimeUnit, this.tryLockTime, tuple, locator);
} }
@Override @Override
public void unlock(Locator locator) throws StrolchLockException { public void unlock(Locator locator) throws StrolchLockException {
TypedTuple<ReentrantLock, Long> tuple = this.lockMap.get(locator); TypedTuple<Lock, Long> tuple = this.lockMap.get(locator);
ReentrantLock lock = tuple.getFirst(); Lock lock = tuple.getFirst();
if (lock == null || !lock.isHeldByCurrentThread()) { if (lock == null || !lock.isHeldByCurrentThread()) {
logger.error(MessageFormat.format("Trying to unlock not locked element {0}", locator)); //$NON-NLS-1$ logger.error(MessageFormat.format("Trying to unlock not locked element {0}", locator));
} else { } else {
// logger.debug("unlocking " + locator); //$NON-NLS-1$
unlock(lock); unlock(lock);
} }
} }
@Override @Override
public void releaseLock(Locator locator) throws StrolchLockException { public void releaseLock(Locator locator) throws StrolchLockException {
TypedTuple<ReentrantLock, Long> tuple = this.lockMap.get(locator); TypedTuple<Lock, Long> tuple = this.lockMap.get(locator);
ReentrantLock lock = tuple.getFirst(); Lock lock = tuple.getFirst();
if (lock == null) { if (lock == null) {
logger.error(MessageFormat.format("Trying to unlock not locked element {0}", locator)); logger.error(MessageFormat.format("Trying to unlock not locked element {0}", locator));
} else if (!lock.isHeldByCurrentThread()) { } else if (!lock.isHeldByCurrentThread()) {
@ -126,7 +126,6 @@ public class DefaultLockHandler implements LockHandler {
else else
logger.error(MessageFormat.format("Element {0} is not locked!", locator)); logger.error(MessageFormat.format("Element {0} is not locked!", locator));
} else { } else {
//logger.info("releasing lock " + locator); //$NON-NLS-1$
releaseLock(lock); releaseLock(lock);
} }
} }
@ -134,28 +133,31 @@ public class DefaultLockHandler implements LockHandler {
/** /**
* @see java.util.concurrent.locks.ReentrantLock#tryLock(long, TimeUnit) * @see java.util.concurrent.locks.ReentrantLock#tryLock(long, TimeUnit)
*/ */
private void lock(TimeUnit timeUnit, long tryLockTime, TypedTuple<ReentrantLock, Long> tuple, Locator locator) private void lock(TimeUnit timeUnit, long tryLockTime, TypedTuple<Lock, Long> tuple, Locator locator)
throws StrolchLockException { throws StrolchLockException {
try { try {
if (!tuple.getFirst().tryLock() && !tuple.getFirst().tryLock(tryLockTime, timeUnit)) { Lock lock = tuple.getFirst();
String msg = "Thread {0} failed to acquire lock after {1}s for {2}"; //$NON-NLS-1$ if (!lock.tryLock() && !lock.tryLock(tryLockTime, timeUnit)) {
String msg = "Thread {0} failed to acquire lock after {1}s for {2}";
msg = MessageFormat.format(msg, Thread.currentThread().getName(), timeUnit.toSeconds(tryLockTime), msg = MessageFormat.format(msg, Thread.currentThread().getName(), timeUnit.toSeconds(tryLockTime),
locator); locator);
try { Thread owner = lock.getOwner();
logger.error(msg); if (owner == null) {
logger.error("Listing all active threads: "); logger.error("Lock is currently held unknown thread!");
Map<Thread, StackTraceElement[]> allStackTraces = Thread.getAllStackTraces(); logger.error(lock.toString());
for (Thread thread : allStackTraces.keySet()) { } else {
StackTraceElement[] trace = allStackTraces.get(thread); Exception e = new Exception();
StringBuilder sb = new StringBuilder(); e.setStackTrace(owner.getStackTrace());
for (StackTraceElement traceElement : trace) logger.error(MessageFormat.format("Lock is currently held by {0}", owner), e);
sb.append("\n\tat ").append(traceElement); }
logger.error("\nThread " + thread.getName() + ":\n" + sb.toString() + "\n");
} logger.error("Threads waiting on this lock are:");
} catch (Exception e) { for (Thread queuedThread : lock.getQueuedThreads()) {
logger.error("Failed to log active threads: " + e.getMessage(), e); Exception e = new Exception();
e.setStackTrace(queuedThread.getStackTrace());
logger.error("\n" + queuedThread.getName(), e);
} }
throw new StrolchLockException(msg); throw new StrolchLockException(msg);
@ -163,8 +165,6 @@ public class DefaultLockHandler implements LockHandler {
tuple.setSecond(System.currentTimeMillis()); tuple.setSecond(System.currentTimeMillis());
// logger.debug("locked " + locator); //$NON-NLS-1$
} catch (InterruptedException e) { } catch (InterruptedException e) {
throw new StrolchLockException("Interrupted while trying to acquire lock for " + locator, e); throw new StrolchLockException("Interrupted while trying to acquire lock for " + locator, e);
} }
@ -177,8 +177,7 @@ public class DefaultLockHandler implements LockHandler {
try { try {
lock.unlock(); lock.unlock();
} catch (IllegalMonitorStateException e) { } catch (IllegalMonitorStateException e) {
throw new StrolchLockException("IllegalMonitorStateException when trying to unlock: " + e.getMessage(), throw new StrolchLockException("IllegalMonitorStateException when trying to unlock: " + e.getMessage(), e);
e); //$NON-NLS-1$
} }
} }
@ -190,4 +189,21 @@ public class DefaultLockHandler implements LockHandler {
unlock(lock); unlock(lock);
} }
} }
public static class Lock extends ReentrantLock {
public Lock(boolean fair) {
super(fair);
}
@Override
public Thread getOwner() {
return super.getOwner();
}
@Override
public Collection<Thread> getQueuedThreads() {
return super.getQueuedThreads();
}
}
} }