You are viewing a plain text version of this content. The canonical link for it is here.
Posted to oak-commits@jackrabbit.apache.org by md...@apache.org on 2019/03/01 07:20:30 UTC
svn commit: r1854560 - in /jackrabbit/oak/branches/1.8: ./
oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/
oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/
Author: mduerig
Date: Fri Mar 1 07:20:30 2019
New Revision: 1854560
URL: http://svn.apache.org/viewvc?rev=1854560&view=rev
Log:
OAK-8071: Logging to detect commits carrying over from previous GC generation can block other threads from committing
> Merged r1854515
Modified:
jackrabbit/oak/branches/1.8/ (props changed)
jackrabbit/oak/branches/1.8/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/Record.java
jackrabbit/oak/branches/1.8/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/Commit.java
jackrabbit/oak/branches/1.8/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/LockBasedScheduler.java
Propchange: jackrabbit/oak/branches/1.8/
------------------------------------------------------------------------------
--- svn:mergeinfo (original)
+++ svn:mergeinfo Fri Mar 1 07:20:30 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,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,1833833,1834112,1834117,1834287,1834291,1834302,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,1837600,1837657,1837718,1837998,1838076,1838637,1839549,1839570,1839637,1839746,1840019,1840024,1840031,1840226,1840455,1840462,1840574,1840769,1841314,1841352,1842089,1842677,1843175,1843222,1843231,1843398,1843618,1843621,1843652,1843911,1844070,1844325,1844549,1844625,1844627,1844642,1844728,1844775,1844932,1845135,1845336,1845405,1845415,1845730-1845731,1845863,1845865,1846057,1846396,1846429,1846581,1846617,1847096,1848073,1848181-1848182,1848191,1848217,1848822-1848823,1850221,1850837,1850
874,1851533-1851535,1851619,1852120,1852451,1852492,1852528,1852582,1852584,1853141,1853229,1853393,1853429,1853433,1853866,1853870,1853893,1853969,1853997,1854044,1854466
+/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,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,1833833,1834112,1834117,1834287,1834291,1834302,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,1837600,1837657,1837718,1837998,1838076,1838637,1839549,1839570,1839637,1839746,1840019,1840024,1840031,1840226,1840455,1840462,1840574,1840769,1841314,1841352,1842089,1842677,1843175,1843222,1843231,1843398,1843618,1843621,1843652,1843911,1844070,1844325,1844549,1844625,1844627,1844642,1844728,1844775,1844932,1845135,1845336,1845405,1845415,1845730-1845731,1845863,1845865,1846057,1846396,1846429,1846581,1846617,1847096,1848073,1848181-1848182,1848191,1848217,1848822-1848823,1850221,1850837,1850
874,1851533-1851535,1851619,1852120,1852451,1852492,1852528,1852582,1852584,1853141,1853229,1853393,1853429,1853433,1853866,1853870,1853893,1853969,1853997,1854044,1854466,1854515
/jackrabbit/trunk:1345480
Modified: jackrabbit/oak/branches/1.8/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/Record.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/branches/1.8/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/Record.java?rev=1854560&r1=1854559&r2=1854560&view=diff
==============================================================================
--- jackrabbit/oak/branches/1.8/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/Record.java (original)
+++ jackrabbit/oak/branches/1.8/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/Record.java Fri Mar 1 07:20:30 2019
@@ -18,6 +18,7 @@
*/
package org.apache.jackrabbit.oak.segment;
+import org.apache.jackrabbit.oak.segment.file.tar.GCGeneration;
import org.jetbrains.annotations.NotNull;
/**
@@ -83,6 +84,16 @@ class Record {
return new RecordId(segmentId, recordNumber);
}
+ /**
+ * Get the underlying segment's gc generation. Might cause the segment to
+ * get loaded if the generation info is missing
+ * @return the segment's gc generation
+ */
+ @NotNull
+ public GCGeneration getGcGeneration() {
+ return segmentId.getGcGeneration();
+ }
+
//------------------------------------------------------------< Object >--
@Override
Modified: jackrabbit/oak/branches/1.8/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/Commit.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/branches/1.8/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/Commit.java?rev=1854560&r1=1854559&r2=1854560&view=diff
==============================================================================
--- jackrabbit/oak/branches/1.8/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/Commit.java (original)
+++ jackrabbit/oak/branches/1.8/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/Commit.java Fri Mar 1 07:20:30 2019
@@ -23,12 +23,14 @@ import static com.google.common.base.Pre
import org.apache.jackrabbit.oak.api.CommitFailedException;
import org.apache.jackrabbit.oak.segment.SegmentNodeBuilder;
import org.apache.jackrabbit.oak.segment.SegmentNodeState;
+import org.apache.jackrabbit.oak.segment.file.tar.GCGeneration;
import org.apache.jackrabbit.oak.spi.commit.CommitHook;
import org.apache.jackrabbit.oak.spi.commit.CommitInfo;
import org.apache.jackrabbit.oak.spi.state.ConflictAnnotatingRebaseDiff;
import org.apache.jackrabbit.oak.spi.state.NodeBuilder;
import org.apache.jackrabbit.oak.spi.state.NodeState;
import org.jetbrains.annotations.NotNull;
+import org.jetbrains.annotations.Nullable;
/**
* A {@code Commit} instance represents a set of related changes, which when
@@ -41,6 +43,8 @@ public class Commit {
private final CommitHook hook;
private final CommitInfo info;
+ private volatile GCGeneration gcGeneration;
+
public Commit(@NotNull NodeBuilder changes, @NotNull CommitHook hook, @NotNull CommitInfo info) {
checkNotNull(changes);
checkArgument(changes instanceof SegmentNodeBuilder);
@@ -51,6 +55,30 @@ public class Commit {
}
/**
+ * This method makes a best effort on getting the gc generation of the current commit.
+ * However it avoids causing a write ahead action by calling {@link NodeBuilder#getName(String)}
+ * on the changes in this commit.
+ *
+ * @return the gc generation of this commit or {@code null} if not yet available.
+ */
+ @Nullable
+ public GCGeneration getGCGeneration() {
+ return gcGeneration;
+ }
+
+ @NotNull
+ private NodeState getBeforeState() {
+ return changes.getBaseState();
+ }
+
+ @NotNull
+ private SegmentNodeState getAfterState() {
+ SegmentNodeState after = changes.getNodeState();
+ gcGeneration = after.getGcGeneration();
+ return after;
+ }
+
+ /**
* Apply the changes represented by this commit to the passed {@code base}
* node state.
*
@@ -63,19 +91,19 @@ public class Commit {
*/
public SegmentNodeState apply(SegmentNodeState base) throws CommitFailedException {
SegmentNodeBuilder builder = base.builder();
- if (SegmentNodeState.fastEquals(changes.getBaseState(), base.getChildNode(ROOT))) {
+ if (SegmentNodeState.fastEquals(getBeforeState(), base.getChildNode(ROOT))) {
// use a shortcut when there are no external changes
- NodeState before = changes.getBaseState();
- NodeState after = changes.getNodeState();
+ NodeState before = getBeforeState();
+ NodeState after = getAfterState();
builder.setChildNode(ROOT, hook.processCommit(before, after, info));
} else {
// there were some external changes, so do the full rebase
ConflictAnnotatingRebaseDiff diff = new ConflictAnnotatingRebaseDiff(builder.child(ROOT));
- changes.getNodeState().compareAgainstBaseState(changes.getBaseState(), diff);
+ getAfterState().compareAgainstBaseState(getBeforeState(), diff);
// apply commit hooks on the rebased changes
builder.setChildNode(ROOT, hook.processCommit(builder.getBaseState().getChildNode(ROOT),
- builder.getNodeState().getChildNode(ROOT), info));
+ builder.getNodeState().getChildNode(ROOT), info));
}
return builder.getNodeState();
}
@@ -94,11 +122,11 @@ public class Commit {
* the same semantics as
* {@link SegmentNodeState#fastEquals(NodeState, NodeState)}, which cannot
* guarantee against false negatives.
- *
+ *
* @return {@code true}, if the commit has changes.
*/
public boolean hasChanges() {
- return !SegmentNodeState.fastEquals(changes.getBaseState(), changes.getNodeState());
+ return !SegmentNodeState.fastEquals(getBeforeState(), getAfterState());
}
public CommitInfo info() {
Modified: jackrabbit/oak/branches/1.8/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/LockBasedScheduler.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/branches/1.8/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/LockBasedScheduler.java?rev=1854560&r1=1854559&r2=1854560&view=diff
==============================================================================
--- jackrabbit/oak/branches/1.8/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/LockBasedScheduler.java (original)
+++ jackrabbit/oak/branches/1.8/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/LockBasedScheduler.java Fri Mar 1 07:20:30 2019
@@ -45,6 +45,7 @@ import org.apache.jackrabbit.oak.segment
import org.apache.jackrabbit.oak.segment.SegmentNodeStoreStats;
import org.apache.jackrabbit.oak.segment.SegmentOverflowException;
import org.apache.jackrabbit.oak.segment.SegmentReader;
+import org.apache.jackrabbit.oak.segment.file.tar.GCGeneration;
import org.apache.jackrabbit.oak.spi.commit.ChangeDispatcher;
import org.apache.jackrabbit.oak.spi.commit.CommitInfo;
import org.apache.jackrabbit.oak.spi.commit.Observable;
@@ -53,8 +54,10 @@ import org.apache.jackrabbit.oak.spi.sta
import org.apache.jackrabbit.oak.spi.state.NodeState;
import org.apache.jackrabbit.oak.stats.StatisticsProvider;
import org.jetbrains.annotations.NotNull;
+import org.jetbrains.annotations.Nullable;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
+
public class LockBasedScheduler implements Scheduler {
public static class LockBasedSchedulerBuilder {
@@ -122,6 +125,13 @@ public class LockBasedScheduler implemen
*/
private static final double SCHEDULER_FETCH_COMMIT_DELAY_QUANTILE = Double
.parseDouble(System.getProperty("oak.scheduler.fetch.commitDelayQuantile", "0.5"));
+
+ /**
+ * Flag controlling the number of milliseconds after which warnings are logged
+ * when threads ready to commit have to wait for a commit in progress.
+ */
+ private static final int COMMIT_WAIT_WARN_MILLIS = Integer
+ .getInteger("oak.segmentNodeStore.commitWaitWarnMillis", 60000);
/**
* Maximum number of milliseconds to wait before re-attempting to update the current
@@ -158,6 +168,50 @@ public class LockBasedScheduler implemen
private final Random random = new Random();
+ private final CommitSemaphoreLogging commitSemaphoreLogging = new CommitSemaphoreLogging();
+
+ /*
+ * Logging of commits that are either blocked for longer than COMMIT_WAIT_WARN_MILLIS
+ * or on a commit that crossed the gc boundary. See OAK-8071.
+ */
+ private class CommitSemaphoreLogging {
+
+ @Nullable
+ private volatile Commit commit;
+
+ private volatile long timeStamp;
+
+ public void commitStarted(@NotNull Commit commit) {
+ this.commit = commit;
+ this.timeStamp = System.currentTimeMillis();
+ }
+
+ public void commitEnded() {
+ this.commit = null;
+ }
+
+ public void warnOnBlockingCommit() {
+ Commit currentCommit = commit;
+ GCGeneration headGeneration = head.get().getGcGeneration();
+ GCGeneration commitGeneration = currentCommit == null
+ ? null
+ : currentCommit.getGCGeneration();
+ long dt = System.currentTimeMillis() - timeStamp;
+ boolean isBlocking = currentCommit != null && dt > COMMIT_WAIT_WARN_MILLIS;
+ boolean isOldGeneration = commitGeneration != null
+ && headGeneration.getFullGeneration() > commitGeneration.getFullGeneration();
+
+ if (isBlocking) {
+ log.warn("This commit is blocked by a commit that is in progress since {} ms", dt);
+ }
+
+ if (isOldGeneration) {
+ log.warn("The commit in progress is from an old GC generation {}. Head is at {}",
+ commitGeneration, headGeneration);
+ }
+ }
+ }
+
public LockBasedScheduler(LockBasedSchedulerBuilder builder) {
if (COMMIT_FAIR_LOCK) {
log.info("Initializing SegmentNodeStore with the commitFairLock option enabled.");
@@ -214,6 +268,8 @@ public class LockBasedScheduler implemen
boolean queued = false;
try {
+ commitSemaphoreLogging.warnOnBlockingCommit();
+
long queuedTime = -1;
if (commitSemaphore.availablePermits() < 1) {
@@ -223,6 +279,7 @@ public class LockBasedScheduler implemen
}
commitSemaphore.acquire();
+ commitSemaphoreLogging.commitStarted(commit);
try {
if (queued) {
long dequeuedTime = System.nanoTime();
@@ -242,6 +299,7 @@ public class LockBasedScheduler implemen
return merged;
} finally {
+ commitSemaphoreLogging.commitEnded();
commitSemaphore.release();
}
} catch (InterruptedException e) {