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/02/28 09:58:13 UTC
svn commit: r1854515 - in
/jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment:
Record.java scheduler/Commit.java scheduler/LockBasedScheduler.java
Author: mduerig
Date: Thu Feb 28 09:58:13 2019
New Revision: 1854515
URL: http://svn.apache.org/viewvc?rev=1854515&view=rev
Log:
OAK-8071: Logging to detect commits carrying over from previous GC generation can block other threads from committing
Log warnings for commits being blocked on the current commit taking a long time or the current commit crossing a gc boundary.
Modified:
jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/Record.java
jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/Commit.java
jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/LockBasedScheduler.java
Modified: jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/Record.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/Record.java?rev=1854515&r1=1854514&r2=1854515&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/Record.java (original)
+++ jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/Record.java Thu Feb 28 09:58:13 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/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/Commit.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/Commit.java?rev=1854515&r1=1854514&r2=1854515&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/Commit.java (original)
+++ jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/Commit.java Thu Feb 28 09:58:13 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/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/LockBasedScheduler.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/LockBasedScheduler.java?rev=1854515&r1=1854514&r2=1854515&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/LockBasedScheduler.java (original)
+++ jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/scheduler/LockBasedScheduler.java Thu Feb 28 09:58:13 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;
@@ -52,8 +53,10 @@ import org.apache.jackrabbit.oak.spi.com
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;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
+
public class LockBasedScheduler implements Scheduler {
public static class LockBasedSchedulerBuilder {
@@ -111,6 +114,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
@@ -147,6 +157,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.");
@@ -202,6 +256,8 @@ public class LockBasedScheduler implemen
boolean queued = false;
try {
+ commitSemaphoreLogging.warnOnBlockingCommit();
+
long queuedTime = -1;
if (commitSemaphore.availablePermits() < 1) {
@@ -211,6 +267,7 @@ public class LockBasedScheduler implemen
}
commitSemaphore.acquire();
+ commitSemaphoreLogging.commitStarted(commit);
try {
if (queued) {
long dequeuedTime = System.nanoTime();
@@ -228,6 +285,7 @@ public class LockBasedScheduler implemen
return merged;
} finally {
+ commitSemaphoreLogging.commitEnded();
commitSemaphore.release();
}
} catch (InterruptedException e) {