svn commit: r1825065 - /jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java

[reschke]

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;
         }
     }