improve BackgroundLeaseUpdate warning messages
@@ -3131,27 +3131,38 @@ public final class DocumentNodeStore
/** OAK-4859 : log if time between two renewClusterIdLease calls is too long **/
private long lastRenewClusterIdLeaseCall = -1;
+ /** elapsed time for previous update operation **/
+ private long elapsedForPreviousRenewal = -1;
+
+ private static int INTERVAL_MS = 1000;
+ private static int TOLERANCE_FOR_WARNING_MS = 2000;
+
BackgroundLeaseUpdate(DocumentNodeStore nodeStore,
AtomicBoolean isDisposed) {
- super(nodeStore, isDisposed, Suppliers.ofInstance(1000));
+ super(nodeStore, isDisposed, Suppliers.ofInstance(INTERVAL_MS));
}
@Override
protected void execute(@Nonnull DocumentNodeStore nodeStore) {
// OAK-4859 : keep track of invocation time of renewClusterIdLease
// and warn if time since last call is longer than 5sec
- final long now = System.currentTimeMillis();
- if (lastRenewClusterIdLeaseCall <= 0) {
- lastRenewClusterIdLeaseCall = now;
- } else {
+ Clock clock = nodeStore.getClock();
+ long now = clock.getTime();
+
+ if (lastRenewClusterIdLeaseCall >= 0) {
final long diff = now - lastRenewClusterIdLeaseCall;
- if (diff > 5000) {
- LOG.warn("BackgroundLeaseUpdate.execute: time since last renewClusterIdLease() call longer than expected: {}ms", diff);
+ if (diff > INTERVAL_MS + TOLERANCE_FOR_WARNING_MS) {
+ String renewTimeMessage = elapsedForPreviousRenewal <= 0 ? ""
+ : String.format(" (of which the last update operation took %dms)", elapsedForPreviousRenewal);
+ LOG.warn(
+ "BackgroundLeaseUpdate.execute: time since last renewClusterIdLease() call longer than expected: {}ms{} (expected ~{}ms)",
+ diff, renewTimeMessage, INTERVAL_MS);
}
- lastRenewClusterIdLeaseCall = now;
}
- // first renew the clusterId lease
+ lastRenewClusterIdLeaseCall = now;
+
nodeStore.renewClusterIdLease();
+ elapsedForPreviousRenewal = clock.getTime() - now;
}
}
