improved time keeping in LockUtil, generating time stamps only every second in a timer, avoiding MillisecondTimePoint.now()

This commit is contained in:
Axel Uhl committed 2015-07-26 03:17:03 +02:00
1 parent 2ea9c1abc1
commit dd92dbff2b
1 file changed
+21 -6
@@ -4,6 +4,8 @@ import java.util.HashMap;
import java.util.HashSet;
import java.util.Map;
import java.util.Set;
import java.util.Timer;
import java.util.TimerTask;
import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.locks.Lock;
@@ -12,6 +14,7 @@ import java.util.concurrent.locks.ReentrantReadWriteLock.ReadLock;
import java.util.logging.Level;
import java.util.logging.Logger;
import com.sap.sse.common.Duration;
import com.sap.sse.common.TimePoint;
import com.sap.sse.common.Util;
import com.sap.sse.common.impl.MillisecondsTimePoint;
@@ -53,6 +56,18 @@ public class LockUtil {
private static final Logger logger = Logger.getLogger(Util.class.getName());
private static final Map<NamedReentrantReadWriteLock, TimePoint> lastTimeWriteLockWasObtained = new ConcurrentWeakHashMap<NamedReentrantReadWriteLock, TimePoint>();
private static TimePoint timePointNoOlderThanOneSecond;
static {
new Timer("LockUtil timestamp generator", /* isDaemon */ true).schedule(
new TimerTask() {
@Override
public void run() {
timePointNoOlderThanOneSecond = MillisecondsTimePoint.now();
}
}, /* delay 0 means immediate execution */ 0l, /* period 1s */ 1000l);
}
/**
* Tells how many other threads propagated which held lock to the key thread. During propagation, a lock is
* considered held if it is really locked by the propagating thread or if the propagating thread received it itself
@@ -86,7 +101,7 @@ public class LockUtil {
public static void lockForWrite(NamedReentrantReadWriteLock lock) {
acquireLockVirtuallyOrActually(lock, lock.writeLock(), ReadOrWrite.WRITE);
lastTimeWriteLockWasObtained.put(lock, MillisecondsTimePoint.now());
lastTimeWriteLockWasObtained.put(lock, timePointNoOlderThanOneSecond);
}
private static void acquireLockVirtuallyOrActually(NamedReentrantReadWriteLock lock, final Lock readOrWriteLock, final ReadOrWrite readOrWrite) {
@@ -150,12 +165,12 @@ public class LockUtil {
+ " to be unlocked but no time recorded for when it was last obtained.\n"
+ "This is where the lock interaction happened:\n" + getCurrentStackTrace());
} else {
TimePoint now = MillisecondsTimePoint.now();
final long heldWriteLockForMillis = now.asMillis() - timePointWriteLockWasObtained.asMillis();
if (heldWriteLockForMillis > 10000l) {
TimePoint now = timePointNoOlderThanOneSecond;
final Duration heldWriteLockForMillis = timePointWriteLockWasObtained.until(now);
if (heldWriteLockForMillis.compareTo(Duration.ONE_SECOND.times(10)) > 0) {
String stackTrace = getCurrentStackTrace();
logger.info("write lock " + lock.getName() + " was held for more than 10s (" + heldWriteLockForMillis
+ "ms). It got unlocked here: " + stackTrace);
logger.info("write lock " + lock.getName() + " was approximately held for more than 10s (" + heldWriteLockForMillis
+ "). It got unlocked here: " + stackTrace);
}
}
}