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

[reschke]

Author: reschke
Date: Wed May 15 14:15:21 2019
New Revision: 1859294

URL: http://svn.apache.org/viewvc?rev=1859294&view=rev
Log:
OAK-8312: NodeDocumentSweeper: improve progress logging

Modified:
    
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/NodeDocumentSweeper.java

Modified: 
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/NodeDocumentSweeper.java
URL: 
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/NodeDocumentSweeper.java?rev=1859294&r1=1859293&r2=1859294&view=diff
==============================================================================
--- 
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/NodeDocumentSweeper.java
 (original)
+++ 
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/NodeDocumentSweeper.java
 Wed May 15 14:15:21 2019
@@ -18,10 +18,12 @@ package org.apache.jackrabbit.oak.plugin
 
 import java.util.List;
 import java.util.Map;
+import java.util.concurrent.TimeUnit;
 
 import com.google.common.base.Function;
 import com.google.common.base.Predicate;
 
+import org.apache.jackrabbit.oak.commons.TimeDurationFormatter;
 import org.apache.jackrabbit.oak.plugins.document.util.Utils;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.Nullable;
@@ -52,6 +54,8 @@ final class NodeDocumentSweeper {
 
     private static final int INVALIDATE_BATCH_SIZE = 100;
 
+    private static final long LOGINTERVALMS = TimeUnit.MINUTES.toMillis(1);
+
     private final RevisionContext context;
 
     private final int clusterId;
@@ -62,7 +66,10 @@ final class NodeDocumentSweeper {
 
     private Revision head;
 
-    private long documentCount;
+    private long totalCount;
+    private long lastCount;
+    private long startOfScan;
+    private long lastLog;
 
     /**
      * Creates a new sweeper for the given context. The sweeper is initialized
@@ -129,7 +136,11 @@ final class NodeDocumentSweeper {
                                   NodeDocumentSweepListener listener)
             throws DocumentStoreException {
         head = headRevision.getRevision(clusterId);
-        documentCount = 0;
+        totalCount = 0;
+        lastCount = 0;
+        startOfScan = context.getClock().getTime();
+        lastLog = startOfScan;
+
         if (head == null) {
             LOG.warn("Head revision does not have an entry for " +
                             "clusterId {}. Sweeping of documents is skipped.",
@@ -185,9 +196,29 @@ final class NodeDocumentSweeper {
                 }
             }
         }
-        if (++documentCount % 100000 == 0) {
-            LOG.info("Checked {} documents so far", documentCount);
+
+        totalCount++;
+        lastCount++;
+        long now = context.getClock().getTime();
+        long lastElapsed = now - lastLog;
+
+        if (lastElapsed >= LOGINTERVALMS) {
+            TimeDurationFormatter df = TimeDurationFormatter.forLogging();
+
+            long totalElapsed = now - startOfScan;
+            long totalRateMin = (totalCount * TimeUnit.MINUTES.toMillis(1)) / 
totalElapsed;
+            long lastRateMin = (lastCount * TimeUnit.MINUTES.toMillis(1)) / 
lastElapsed;
+
+            String message = String.format(
+                    "Sweep on cluster node [%d]: %d nodes scanned in %s 
(~%d/m) - last interval %d nodes in %s (~%d/m)",
+                    clusterId, totalCount, df.format(totalElapsed, 
TimeUnit.MILLISECONDS), totalRateMin, lastCount,
+                    df.format(lastElapsed, TimeUnit.MILLISECONDS), 
lastRateMin);
+
+            LOG.info(message);
+            lastLog = now;
+            lastCount = 0;
         }
+
         return op.hasChanges() ? op : null;
     }