Author: reschke
Date: Thu May 16 19:48:27 2019
New Revision: 1859407
URL: http://svn.apache.org/viewvc?rev=1859407&view=rev
Log:
OAK-8312: MissingLastRevSeeker and NodeDocumentSweeper: improve progress
logging (ported to 1.10)
Modified:
jackrabbit/oak/branches/1.10/ (props changed)
jackrabbit/oak/branches/1.10/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/LastRevRecoveryAgent.java
jackrabbit/oak/branches/1.10/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/NodeDocumentSweeper.java
Propchange: jackrabbit/oak/branches/1.10/
------------------------------------------------------------------------------
--- svn:mergeinfo (original)
+++ svn:mergeinfo Thu May 16 19:48:27 2019
@@ -1,3 +1,3 @@
/jackrabbit/oak/branches/1.0:1665962
-/jackrabbit/oak/trunk:1850874,1850882,1851236,1851253,1851451,1851533-1851535,1851619,1852052,1852084,1852120,1852135,1852451,1852492-1852493,1852528,1852582,1852584,1852601,1852920,1853083,1853141,1853229,1853393,1853429,1853433,1853441,1853866,1853868,1853870,1853893,1853969,1853997,1854034,1854044,1854055,1854058,1854113,1854373,1854377,1854380,1854385,1854401,1854403,1854455,1854461-1854462,1854466,1854468,1854515,1854533,1854539,1854701,1854773-1854774,1854827,1854848,1854859,1854930,1854990-1854991,1855032,1855221,1855477-1855478,1855776,1855993,1856049,1856056,1856538,1856545,1857000,1857010,1857104,1857159,1857212,1857221,1857238,1857247,1857253,1857294,1857314,1857577,1857635,1857638,1857640,1857687,1857936,1858032,1858053,1858123,1858139,1858571,1858578,1858810,1858931,1859231
+/jackrabbit/oak/trunk:1850874,1850882,1851236,1851253,1851451,1851533-1851535,1851619,1852052,1852084,1852120,1852135,1852451,1852492-1852493,1852528,1852582,1852584,1852601,1852920,1853083,1853141,1853229,1853393,1853429,1853433,1853441,1853866,1853868,1853870,1853893,1853969,1853997,1854034,1854044,1854055,1854058,1854113,1854373,1854377,1854380,1854385,1854401,1854403,1854455,1854461-1854462,1854466,1854468,1854515,1854533,1854539,1854701,1854773-1854774,1854827,1854848,1854859,1854930,1854990-1854991,1855032,1855221,1855477-1855478,1855776,1855993,1856049,1856056,1856538,1856545,1857000,1857010,1857104,1857159,1857212,1857221,1857238,1857247,1857253,1857294,1857314,1857577,1857635,1857638,1857640,1857687,1857936,1858032,1858053,1858123,1858139,1858571,1858578,1858810,1858931,1859231,1859292,1859294
/jackrabbit/trunk:1345480
Modified:
jackrabbit/oak/branches/1.10/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/LastRevRecoveryAgent.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/branches/1.10/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/LastRevRecoveryAgent.java?rev=1859407&r1=1859406&r2=1859407&view=diff
==============================================================================
---
jackrabbit/oak/branches/1.10/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/LastRevRecoveryAgent.java
(original)
+++
jackrabbit/oak/branches/1.10/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/LastRevRecoveryAgent.java
Thu May 16 19:48:27 2019
@@ -31,6 +31,7 @@ import static org.apache.jackrabbit.oak.
import java.util.Collections;
import java.util.Map;
+import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicReference;
import java.util.concurrent.locks.ReentrantLock;
import java.util.function.Consumer;
@@ -41,6 +42,7 @@ import com.google.common.collect.Iterabl
import com.google.common.collect.Sets;
import org.apache.jackrabbit.oak.commons.PathUtils;
+import org.apache.jackrabbit.oak.commons.TimeDurationFormatter;
import org.apache.jackrabbit.oak.plugins.document.util.MapFactory;
import org.apache.jackrabbit.oak.plugins.document.util.Utils;
import org.apache.jackrabbit.oak.stats.Clock;
@@ -72,6 +74,8 @@ public class LastRevRecoveryAgent {
private final Consumer<Integer> afterRecovery;
+ private static final long LOGINTERVALMS = TimeUnit.MINUTES.toMillis(1);
+
public LastRevRecoveryAgent(DocumentStore store,
RevisionContext revisionContext,
MissingLastRevSeeker seeker,
@@ -279,11 +283,34 @@ public class LastRevRecoveryAgent {
Map<String, Revision> knownLastRevOrModification =
MapFactory.getInstance().create();
final JournalEntry changes = JOURNAL.newDocument(store);
- long count = 0;
+ Clock clock = revisionContext.getClock();
+
+ long totalCount = 0;
+ long lastCount = 0;
+ long startOfScan = clock.getTime();
+ long lastLog = startOfScan;
+
for (NodeDocument doc : suspects) {
- count++;
- if (count % 100000 == 0) {
- log.info("Scanned {} suspects so far...", count);
+ totalCount++;
+ lastCount++;
+
+ long now = clock.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(
+ "Recovery for 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;
}
Revision currentLastRev = doc.getLastRev().get(clusterId);
@@ -364,7 +391,7 @@ public class LastRevRecoveryAgent {
"cluster node [{}]: {}", size, clusterId, updates);
} else {
// check deadline before the update
- if (revisionContext.getClock().getTime() > deadline) {
+ if (clock.getTime() > deadline) {
String msg = String.format("Cluster node %d was unable to " +
"perform lastRev recovery for clusterId %d within " +
"deadline: %s", clusterId, clusterId,
Modified:
jackrabbit/oak/branches/1.10/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/NodeDocumentSweeper.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/branches/1.10/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/NodeDocumentSweeper.java?rev=1859407&r1=1859406&r2=1859407&view=diff
==============================================================================
---
jackrabbit/oak/branches/1.10/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/NodeDocumentSweeper.java
(original)
+++
jackrabbit/oak/branches/1.10/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/NodeDocumentSweeper.java
Thu May 16 19:48:27 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;
}
