Author: reschke
Date: Fri May 17 03:16:29 2019
New Revision: 1859412
URL: http://svn.apache.org/viewvc?rev=1859412&view=rev
Log:
OAK-8312: MissingLastRevSeeker and NodeDocumentSweeper: improve progress
logging (ported to 1.8)
Modified:
jackrabbit/oak/branches/1.8/ (props changed)
jackrabbit/oak/branches/1.8/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/LastRevRecoveryAgent.java
jackrabbit/oak/branches/1.8/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/NodeDocumentSweeper.java
Propchange: jackrabbit/oak/branches/1.8/
------------------------------------------------------------------------------
--- svn:mergeinfo (original)
+++ svn:mergeinfo Fri May 17 03:16:29 2019
@@ -1,3 +1,3 @@
/jackrabbit/oak/branches/1.0:1665962
-/jackrabbit/oak/trunk:1820660-1820661,1820729,1820734,1820859,1820861,1820878,1820888,1820947,1821027,1821130,1821140-1821141,1821178,1821237,1821240,1821249,1821258,1821325,1821358,1821361-1821362,1821370,1821375,1821393,1821477,1821487,1821516,1821617,1821663,1821665,1821668,1821681,1821847,1821975-1821983,1822121,1822182,1822201,1822207,1822527,1822642,1822723,1822808,1822850,1822934,1823135,1823163,1823169,1823172,1823655,1823669,1824196,1824198,1824253,1824255,1824896,1824962,1825065,1825362,1825381,1825442,1825448,1825466,1825470-1825471,1825475,1825523,1825525,1825561,1825619-1825621,1825651,1825654,1825992,1826079,1826090,1826096,1826216,1826237,1826338,1826516,1826532,1826551,1826560,1826638,1826640,1826730,1826833,1826932,1826957,1827423,1827472,1827486,1827816,1827977,1828349,1828439,1828502,1828529,1828827,1828868,1828948,1829527,1829534,1829546,1829569,1829587,1829665,1829854,1829864,1829978,1829985,1829987,1829998,1830019,1830048,1830160,1830171,1830197,1830209,1830239
,1830347,1830748,1830911,1830923,1831157-1831158,1831163,1831190,1831374,1831560,1831689,1832258,1832376,1832379,1832535,1833308,1833347,1833702,1833833,1834109,1834112,1834117,1834287,1834291,1834302,1834312,1834326,1834328,1834336,1834428,1834468,1834483,1834610,1834648-1834649,1834681,1834823,1834857-1834858,1835060,1835518,1835521,1835635,1835642,1835780,1835819,1836082,1836121,1836167-1836168,1836170-1836187,1836189-1836196,1836206,1836487,1836493,1836548,1837057,1837274,1837296,1837326,1837475,1837503,1837547,1837569,1837596,1837600,1837657,1837718,1837998,1838076,1838637,1839549,1839570,1839637,1839746,1840019,1840024,1840031,1840226,1840455,1840462,1840574,1840769,1841314,1841352,1841909,1842089,1842677,1843175,1843222,1843231,1843398,1843618,1843621,1843637,1843652,1843669,1843905,1843911,1844070,1844110,1844325,1844549,1844625,1844627,1844642,1844728,1844775,1844932,1845135,1845336,1845405,1845415,1845730-1845731,1845863,1845865,1846057,1846396,1846429,1846581,1846617,1847
088,1847096,1848073,1848181-1848182,1848191,1848217,1848822-1848823,1850221,1850837,1850874,1851533-1851535,1851619,1852120,1852135,1852451,1852492-1852493,1852528,1852582,1852584,1852601,1853141,1853229,1853393,1853429,1853433,1853866,1853868,1853870,1853893,1853969,1853997,1854034,1854044,1854055,1854455,1854461-1854462,1854466,1854515,1854539,1854701,1854773,1854827,1854848,1854859,1854930,1855032,1855776,1856818,1857010,1857247,1857253,1857294,1857314,1857638,1857936,1858032,1858139,1858571,1858578,1858810,1859231
+/jackrabbit/oak/trunk:1820660-1820661,1820729,1820734,1820859,1820861,1820878,1820888,1820947,1821027,1821130,1821140-1821141,1821178,1821237,1821240,1821249,1821258,1821325,1821358,1821361-1821362,1821370,1821375,1821393,1821477,1821487,1821516,1821617,1821663,1821665,1821668,1821681,1821847,1821975-1821983,1822121,1822182,1822201,1822207,1822527,1822642,1822723,1822808,1822850,1822934,1823135,1823163,1823169,1823172,1823655,1823669,1824196,1824198,1824253,1824255,1824896,1824962,1825065,1825362,1825381,1825442,1825448,1825466,1825470-1825471,1825475,1825523,1825525,1825561,1825619-1825621,1825651,1825654,1825992,1826079,1826090,1826096,1826216,1826237,1826338,1826516,1826532,1826551,1826560,1826638,1826640,1826730,1826833,1826932,1826957,1827423,1827472,1827486,1827816,1827977,1828349,1828439,1828502,1828529,1828827,1828868,1828948,1829527,1829534,1829546,1829569,1829587,1829665,1829854,1829864,1829978,1829985,1829987,1829998,1830019,1830048,1830160,1830171,1830197,1830209,1830239
,1830347,1830748,1830911,1830923,1831157-1831158,1831163,1831190,1831374,1831560,1831689,1832258,1832376,1832379,1832535,1833308,1833347,1833702,1833833,1834109,1834112,1834117,1834287,1834291,1834302,1834312,1834326,1834328,1834336,1834428,1834468,1834483,1834610,1834648-1834649,1834681,1834823,1834857-1834858,1835060,1835518,1835521,1835635,1835642,1835780,1835819,1836082,1836121,1836167-1836168,1836170-1836187,1836189-1836196,1836206,1836487,1836493,1836548,1837057,1837274,1837296,1837326,1837475,1837503,1837547,1837569,1837596,1837600,1837657,1837718,1837998,1838076,1838637,1839549,1839570,1839637,1839746,1840019,1840024,1840031,1840226,1840455,1840462,1840574,1840769,1841314,1841352,1841909,1842089,1842677,1843175,1843222,1843231,1843398,1843618,1843621,1843637,1843652,1843669,1843905,1843911,1844070,1844110,1844325,1844549,1844625,1844627,1844642,1844728,1844775,1844932,1845135,1845336,1845405,1845415,1845730-1845731,1845863,1845865,1846057,1846396,1846429,1846581,1846617,1847
088,1847096,1848073,1848181-1848182,1848191,1848217,1848822-1848823,1850221,1850837,1850874,1851533-1851535,1851619,1852120,1852135,1852451,1852492-1852493,1852528,1852582,1852584,1852601,1853141,1853229,1853393,1853429,1853433,1853866,1853868,1853870,1853893,1853969,1853997,1854034,1854044,1854055,1854455,1854461-1854462,1854466,1854515,1854539,1854701,1854773,1854827,1854848,1854859,1854930,1855032,1855776,1856818,1857010,1857247,1857253,1857294,1857314,1857638,1857936,1858032,1858139,1858571,1858578,1858810,1859231,1859292,1859294
/jackrabbit/trunk:1345480
Modified:
jackrabbit/oak/branches/1.8/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/LastRevRecoveryAgent.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/branches/1.8/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/LastRevRecoveryAgent.java?rev=1859412&r1=1859411&r2=1859412&view=diff
==============================================================================
---
jackrabbit/oak/branches/1.8/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/LastRevRecoveryAgent.java
(original)
+++
jackrabbit/oak/branches/1.8/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/LastRevRecoveryAgent.java
Fri May 17 03:16:29 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;
@@ -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;
@@ -69,6 +71,8 @@ public class LastRevRecoveryAgent {
private final MissingLastRevSeeker missingLastRevUtil;
+ private static final long LOGINTERVALMS = TimeUnit.MINUTES.toMillis(1);
+
public LastRevRecoveryAgent(DocumentNodeStore nodeStore,
MissingLastRevSeeker seeker) {
this.nodeStore = nodeStore;
@@ -243,11 +247,34 @@ public class LastRevRecoveryAgent {
Map<String, Revision> knownLastRevOrModification =
MapFactory.getInstance().create();
final JournalEntry changes = JOURNAL.newDocument(docStore);
- long count = 0;
+ Clock clock = nodeStore.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);
Modified:
jackrabbit/oak/branches/1.8/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/NodeDocumentSweeper.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/branches/1.8/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/NodeDocumentSweeper.java?rev=1859412&r1=1859411&r2=1859412&view=diff
==============================================================================
---
jackrabbit/oak/branches/1.8/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/NodeDocumentSweeper.java
(original)
+++
jackrabbit/oak/branches/1.8/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/NodeDocumentSweeper.java
Fri May 17 03:16:29 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;
}
