Author: reschke Date: Thu Feb 22 14:04:38 2018 New Revision: 1825065 URL: http://svn.apache.org/viewvc?rev=1825065&view=rev Log: OAK-7272: improve BackgroundLeaseUpdate warning messages
Modified: jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java Modified: jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java?rev=1825065&r1=1825064&r2=1825065&view=diff ============================================================================== --- jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java (original) +++ jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java Thu Feb 22 14:04:38 2018 @@ -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; } }