Author: mreutegg
Date: Tue Jan 15 16:11:49 2019
New Revision: 1851392
URL: http://svn.apache.org/viewvc?rev=1851392&view=rev
Log:
OAK-7974: Detailed merge metrics
Added:
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/TimingHook.java
(with props)
jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/TimingHookTest.java
(with props)
Modified:
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/Commit.java
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/CommitQueue.java
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreBranch.java
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreStats.java
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreStatsCollector.java
jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreStatsCollectorIT.java
Modified:
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/Commit.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/Commit.java?rev=1851392&r1=1851391&r2=1851392&view=diff
==============================================================================
---
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/Commit.java
(original)
+++
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/Commit.java
Tue Jan 15 16:11:49 2019
@@ -25,6 +25,7 @@ import java.util.LinkedHashSet;
import java.util.List;
import java.util.Map;
import java.util.Set;
+import java.util.concurrent.TimeUnit;
import com.google.common.base.Function;
import com.google.common.collect.Iterables;
@@ -237,7 +238,7 @@ public class Commit {
if (!operations.isEmpty()) {
updateParentChildStatus();
updateBinaryStatus();
- applyToDocumentStore(baseRevision);
+ applyToDocumentStoreWithTiming(baseRevision);
}
}
@@ -260,7 +261,27 @@ public class Commit {
* Apply the changes to the document store.
*/
void applyToDocumentStore() throws ConflictException,
DocumentStoreException {
- applyToDocumentStore(null);
+ applyToDocumentStoreWithTiming(null);
+ }
+
+ /**
+ * Apply the changes to the document store.
+ *
+ * @param baseBranchRevision the base revision of this commit. Currently
only
+ * used for branch commits.
+ * @throws ConflictException if a conflict is detected with another commit.
+ * @throws DocumentStoreException if an error occurs while writing to the
+ * underlying store.
+ */
+ private void applyToDocumentStoreWithTiming(RevisionVector
baseBranchRevision)
+ throws ConflictException, DocumentStoreException {
+ long start = System.nanoTime();
+ try {
+ applyToDocumentStore(baseBranchRevision);
+ } finally {
+ nodeStore.getStatsCollector().doneChangesApplied(
+ TimeUnit.NANOSECONDS.toMicros(System.nanoTime() - start));
+ }
}
/**
Modified:
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/CommitQueue.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/CommitQueue.java?rev=1851392&r1=1851391&r2=1851392&view=diff
==============================================================================
---
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/CommitQueue.java
(original)
+++
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/CommitQueue.java
Tue Jan 15 16:11:49 2019
@@ -33,6 +33,7 @@ import java.util.concurrent.TimeUnit;
import com.google.common.collect.Maps;
+import org.apache.jackrabbit.oak.stats.StatisticsProvider;
import org.jetbrains.annotations.NotNull;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
@@ -59,12 +60,22 @@ final class CommitQueue {
private final RevisionContext context;
+ /**
+ * The default stats collector is a noop.
+ */
+ private DocumentNodeStoreStatsCollector statsCollector
+ = new DocumentNodeStoreStats(StatisticsProvider.NOOP);
+
private long suspendTimeout =
Long.getLong("oak.documentMK.suspendTimeoutMillis", DEFAULT_SUSPEND_TIMEOUT);
CommitQueue(@NotNull RevisionContext context) {
this.context = checkNotNull(context);
}
+ void setStatisticsCollector(@NotNull DocumentNodeStoreStatsCollector
collector) {
+ statsCollector = checkNotNull(collector);
+ }
+
@NotNull
Revision createRevision() {
return createRevisions(1).first();
@@ -250,9 +261,11 @@ final class CommitQueue {
isHead = commits.firstKey().equals(rev);
commitEntry = commits.get(rev);
}
- if (!isHead) {
+ if (isHead) {
+ statsCollector.doneWaitUntilHead(0);
+ } else {
LOG.debug("not head: {}, waiting...", rev);
- commitEntry.await();
+ statsCollector.doneWaitUntilHead(commitEntry.await());
}
try {
c.headOfQueue(rev);
@@ -305,8 +318,11 @@ final class CommitQueue {
/**
* Wait for the latch to be released.
+ *
+ * @return the number of microseconds this method waited.
*/
- void await() {
+ long await() {
+ long start = System.nanoTime();
for (;;) {
try {
LOG.debug("awaiting {}", revision);
@@ -316,6 +332,7 @@ final class CommitQueue {
// retry
}
}
+ return TimeUnit.NANOSECONDS.toMicros(System.nanoTime() - start);
}
}
Modified:
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java?rev=1851392&r1=1851391&r2=1851392&view=diff
==============================================================================
---
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java
(original)
+++
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java
Tue Jan 15 16:11:49 2019
@@ -658,6 +658,7 @@ public final class DocumentNodeStore
new PrefetchDispatcher(getRoot(), executor) :
new ChangeDispatcher(getRoot());
commitQueue = new CommitQueue(this);
+ commitQueue.setStatisticsCollector(nodeStoreStatsCollector);
batchCommitQueue = new BatchCommitQueue(store);
// prepare background threads
backgroundReadThread = new Thread(
@@ -1799,8 +1800,10 @@ public final class DocumentNodeStore
* delay is set to 0.
*
* @param conflictRevisions the revision to become visible.
+ * @return the suspend time in milliseconds.
*/
- void suspendUntilAll(@NotNull Set<Revision> conflictRevisions) {
+ long suspendUntilAll(@NotNull Set<Revision> conflictRevisions) {
+ long time = clock.getTime();
// do not suspend if revision is from another cluster node
// and background read is disabled
if (getAsyncDelay() == 0) {
@@ -1814,6 +1817,7 @@ public final class DocumentNodeStore
} else {
commitQueue.suspendUntilAll(conflictRevisions);
}
+ return clock.getTime() - time;
}
//------------------------< Observable
>------------------------------------
Modified:
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreBranch.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreBranch.java?rev=1851392&r1=1851391&r2=1851392&view=diff
==============================================================================
---
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreBranch.java
(original)
+++
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreBranch.java
Tue Jan 15 16:11:49 2019
@@ -27,6 +27,7 @@ import static org.apache.jackrabbit.oak.
import java.util.HashSet;
import java.util.Random;
import java.util.Set;
+import java.util.concurrent.TimeUnit;
import java.util.concurrent.locks.Lock;
import java.util.concurrent.locks.ReadWriteLock;
@@ -165,7 +166,7 @@ class DocumentNodeStoreBranch implements
Set<Revision> conflictRevisions = new HashSet<Revision>();
long time = System.currentTimeMillis();
int numRetries = 0;
- boolean suspended= false;
+ long suspendMillis = 0;
for (long backoff = MIN_BACKOFF; backoff <= maximumBackoff; backoff *=
2) {
if (ex != null) {
try {
@@ -177,12 +178,13 @@ class DocumentNodeStoreBranch implements
// suspend until conflicting revision is visible
LOG.debug("Suspending until {} is visible. Current
head {}.",
conflictRevisions, store.getHeadRevision());
- suspended = true;
- store.suspendUntilAll(conflictRevisions);
+ suspendMillis +=
store.suspendUntilAll(conflictRevisions);
conflictRevisions.clear();
LOG.debug("Resumed. Current head {}.",
store.getHeadRevision());
} else {
- Thread.sleep(backoff + RANDOM.nextInt((int)
Math.min(backoff, Integer.MAX_VALUE)));
+ long sleepMillis = backoff + RANDOM.nextInt((int)
Math.min(backoff, Integer.MAX_VALUE));
+ suspendMillis += sleepMillis;
+ Thread.sleep(sleepMillis);
}
perfLogger.end(start, 1, "Merge - Retry attempt [{}]",
numRetries);
} catch (InterruptedException e) {
@@ -193,7 +195,7 @@ class DocumentNodeStoreBranch implements
try {
NodeState result = branchState.merge(checkNotNull(hook),
checkNotNull(info), exclusive);
- store.getStatsCollector().doneMerge(numRetries,
System.currentTimeMillis() - time, suspended, exclusive);
+ store.getStatsCollector().doneMerge(numRetries,
System.currentTimeMillis() - time, suspendMillis, exclusive);
return result;
} catch (FailedWithConflictException e) {
ex = e;
@@ -212,7 +214,7 @@ class DocumentNodeStoreBranch implements
}
// if we get here retrying failed
time = System.currentTimeMillis() - time;
- store.getStatsCollector().failedMerge(numRetries, time, suspended,
exclusive);
+ store.getStatsCollector().failedMerge(numRetries, time, suspendMillis,
exclusive);
String msg = ex.getMessage() + " (retries " + numRetries + ", " + time
+ " ms)";
throw new CommitFailedException(ex.getSource(), ex.getType(),
ex.getCode(), msg, ex.getCause());
@@ -230,7 +232,7 @@ class DocumentNodeStoreBranch implements
@Nullable
private Lock acquireMergeLock(boolean exclusive)
throws CommitFailedException {
- final long start = perfLogger.start();
+ final long start = System.nanoTime();
Lock lock;
if (exclusive) {
lock = mergeLock.writeLock();
@@ -251,6 +253,8 @@ class DocumentNodeStoreBranch implements
LOG.info("Time out while acquiring merge lock ({})", mode);
lock = null;
}
+ long micros = TimeUnit.NANOSECONDS.toMicros(System.nanoTime() - start);
+ store.getStatsCollector().doneMergeLockAcquired(micros);
return lock;
}
@@ -518,7 +522,9 @@ class DocumentNodeStoreBranch implements
boolean success = false;
NodeState previousHead = head;
try {
- NodeState toCommit = hook.processCommit(base, head, info);
+ DocumentNodeStoreStatsCollector stats =
store.getStatsCollector();
+ NodeState toCommit = TimingHook.wrap(hook, (time, unit) ->
stats.doneCommitHookProcessed(unit.toMicros(time)))
+ .processCommit(base, head, info);
try {
NodeState newHead;
if (this != branchState) {
@@ -526,7 +532,7 @@ class DocumentNodeStoreBranch implements
Persisted p = branchState.persist();
RevisionVector branchRev =
p.getHead().getRootRevision();
newHead = store.getRoot(store.merge(branchRev,
info));
-
store.getStatsCollector().doneMergeBranch(p.numCommits);
+ stats.doneMergeBranch(p.numCommits);
} else {
newHead =
DocumentNodeStoreBranch.this.persist(toCommit, base, info);
}
@@ -637,12 +643,14 @@ class DocumentNodeStoreBranch implements
rebase();
previousHead = head;
checkForConflicts();
- NodeState toCommit = checkNotNull(hook).processCommit(base,
head, info);
+ DocumentNodeStoreStatsCollector stats =
store.getStatsCollector();
+ NodeState toCommit = TimingHook.wrap(checkNotNull(hook),
(time, unit) -> stats.doneCommitHookProcessed(unit.toMicros(time)))
+ .processCommit(base, head, info);
persistTransientHead(toCommit);
DocumentNodeState newRoot =
store.getRoot(store.merge(head.getRootRevision(), info));
success = true;
branchState = new Merged(base);
- store.getStatsCollector().doneMergeBranch(numCommits);
+ stats.doneMergeBranch(numCommits);
return newRoot;
} catch (CommitFailedException e) {
throw e;
Modified:
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreStats.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreStats.java?rev=1851392&r1=1851391&r2=1851392&view=diff
==============================================================================
---
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreStats.java
(original)
+++
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreStats.java
Tue Jan 15 16:11:49 2019
@@ -54,6 +54,11 @@ public class DocumentNodeStoreStats impl
private static final String MERGE_SUCCESS_SUSPENDED =
"DOCUMENT_NS_MERGE_SUCCESS_SUSPENDED";
private static final String MERGE_SUCCESS_EXCLUSIVE =
"DOCUMENT_NS_MERGE_SUCCESS_EXCLUSIVE";
static final String MERGE_FAILED_EXCLUSIVE =
"DOCUMENT_NS_MERGE_FAILED_EXCLUSIVE";
+ private static final String HEAD_OF_QUEUE_WAIT_TIME =
"DOCUMENT_NS_HEAD_OF_QUEUE_WAIT_TIME";
+ private static final String MERGE_SUSPEND_TIME =
"DOCUMENT_NS_MERGE_SUSPEND_TIME";
+ private static final String MERGE_LOCK_TIME =
"DOCUMENT_NS_MERGE_LOCK_TIME";
+ private static final String MERGE_COMMIT_HOOK_TIME =
"DOCUMENT_NS_MERGE_COMMIT_HOOK_TIME";
+ private static final String MERGE_CHANGES_APPLIED_TIME =
"DOCUMENT_NS_MERGE_CHANGES_APPLIED_TIME";
static final String BRANCH_COMMIT_COUNT =
"DOCUMENT_NS_BRANCH_COMMIT_COUNT";
static final String MERGE_BRANCH_COMMIT_COUNT =
"DOCUMENT_NS_MERGE_BRANCH_COMMIT_COUNT";
@@ -88,6 +93,11 @@ public class DocumentNodeStoreStats impl
private final MeterStats mergeSuccessExclusive;
private final MeterStats mergeSuccessSuspended;
private final MeterStats mergeFailedExclusive;
+ private final TimerStats headOfQueueWaitTime;
+ private final TimerStats mergeSuspendTime;
+ private final TimerStats mergeLockTime;
+ private final TimerStats mergeCommitHookTime;
+ private final TimerStats mergeChangesApplied;
// branch stats
private final MeterStats branchCommitRate;
@@ -121,6 +131,11 @@ public class DocumentNodeStoreStats impl
mergeSuccessExclusive = sp.getMeter(MERGE_SUCCESS_EXCLUSIVE,
StatsOptions.METRICS_ONLY);
mergeSuccessSuspended = sp.getMeter(MERGE_SUCCESS_SUSPENDED,
StatsOptions.METRICS_ONLY);
mergeFailedExclusive = sp.getMeter(MERGE_FAILED_EXCLUSIVE,
StatsOptions.DEFAULT); //Enable time series
+ headOfQueueWaitTime = sp.getTimer(HEAD_OF_QUEUE_WAIT_TIME,
StatsOptions.METRICS_ONLY);
+ mergeSuspendTime = sp.getTimer(MERGE_SUSPEND_TIME,
StatsOptions.METRICS_ONLY);
+ mergeLockTime = sp.getTimer(MERGE_LOCK_TIME,
StatsOptions.METRICS_ONLY);
+ mergeCommitHookTime = sp.getTimer(MERGE_COMMIT_HOOK_TIME,
StatsOptions.METRICS_ONLY);
+ mergeChangesApplied = sp.getTimer(MERGE_CHANGES_APPLIED_TIME,
StatsOptions.METRICS_ONLY);
branchCommitRate = sp.getMeter(BRANCH_COMMIT_COUNT,
StatsOptions.DEFAULT);
mergeBranchCommitRate = sp.getMeter(MERGE_BRANCH_COMMIT_COUNT,
StatsOptions.DEFAULT);
@@ -173,24 +188,45 @@ public class DocumentNodeStoreStats impl
}
@Override
- public void doneMerge(int numRetries, long time, boolean suspended,
boolean exclusive) {
+ public void doneMerge(int numRetries, long timeMillis, long suspendMillis,
boolean exclusive) {
mergeSuccessRate.mark();
mergeSuccessRetries.update(numRetries);
- mergeSuccessTime.update(time, TimeUnit.MILLISECONDS);
+ mergeSuccessTime.update(timeMillis, TimeUnit.MILLISECONDS);
if (exclusive) {
mergeSuccessExclusive.mark();
}
- if (suspended) {
+ mergeSuspendTime.update(suspendMillis, TimeUnit.MILLISECONDS);
+ if (suspendMillis > 0) {
mergeSuccessSuspended.mark();
}
}
@Override
- public void failedMerge(int numRetries, long timeMillis, boolean
suspended, boolean exclusive) {
+ public void failedMerge(int numRetries, long timeMillis, long
suspendMillis, boolean exclusive) {
if (exclusive){
mergeFailedExclusive.mark();
}
}
+
+ @Override
+ public void doneWaitUntilHead(long waitMicros) {
+ headOfQueueWaitTime.update(waitMicros, TimeUnit.MICROSECONDS);
+ }
+
+ @Override
+ public void doneMergeLockAcquired(long timeMicros) {
+ mergeLockTime.update(timeMicros, TimeUnit.MICROSECONDS);
+ }
+
+ @Override
+ public void doneCommitHookProcessed(long timeMicros) {
+ mergeCommitHookTime.update(timeMicros, TimeUnit.MICROSECONDS);
+ }
+
+ @Override
+ public void doneChangesApplied(long timeMicros) {
+ mergeChangesApplied.update(timeMicros, TimeUnit.MICROSECONDS);
+ }
}
Modified:
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreStatsCollector.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreStatsCollector.java?rev=1851392&r1=1851391&r2=1851392&view=diff
==============================================================================
---
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreStatsCollector.java
(original)
+++
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreStatsCollector.java
Tue Jan 15 16:11:49 2019
@@ -59,18 +59,51 @@ public interface DocumentNodeStoreStatsC
*
* @param numRetries the number of retries that were necessary.
* @param timeMillis the time in milliseconds it took to merge the changes.
- * @param suspended whether the merge had to be suspended.
+ * @param suspendMillis the time in milliseconds the merge was suspended.
* @param exclusive whether the merge was holding an exclusive lock.
*/
- void doneMerge(int numRetries, long timeMillis, boolean suspended, boolean
exclusive);
+ void doneMerge(int numRetries, long timeMillis, long suspendMillis,
boolean exclusive);
/**
* Reports to the collector that a merge failed.
*
* @param numRetries the number of retries that were done.
* @param timeMillis the time in milliseconds it took to attempt the merge.
- * @param suspended whether the merge had to be suspended.
+ * @param suspendMillis the time in milliseconds the merge was suspended.
* @param exclusive whether the merge was holding an exclusive lock.
*/
- void failedMerge(int numRetries, long timeMillis, boolean suspended,
boolean exclusive);
+ void failedMerge(int numRetries, long timeMillis, long suspendMillis,
boolean exclusive);
+
+ /**
+ * Reports to the collector that a commit finished waiting to become the
+ * head of the commit queue.
+ *
+ * @param waitMicros the time it waited in microseconds to be come
+ * the head of the queue.
+ */
+ void doneWaitUntilHead(long waitMicros);
+
+ /**
+ * Reports to the collector that the commit acquired the merge lock in the
+ * given time.
+ *
+ * @param timeMicros the time in microseconds.
+ */
+ void doneMergeLockAcquired(long timeMicros);
+
+ /**
+ * Reports to the collector that the commit hook processed a commit in the
+ * given time.
+ *
+ * @param timeMicros the time in microseconds.
+ */
+ void doneCommitHookProcessed(long timeMicros);
+
+ /**
+ * Reports to the collector that the commit applied the changes to the
+ * {@code DocumentStore} in the given time.
+ *
+ * @param timeMicros the time in microseconds.
+ */
+ void doneChangesApplied(long timeMicros);
}
Added:
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/TimingHook.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/TimingHook.java?rev=1851392&view=auto
==============================================================================
---
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/TimingHook.java
(added)
+++
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/TimingHook.java
Tue Jan 15 16:11:49 2019
@@ -0,0 +1,76 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.apache.jackrabbit.oak.plugins.document;
+
+import java.util.concurrent.TimeUnit;
+
+import org.apache.jackrabbit.oak.api.CommitFailedException;
+import org.apache.jackrabbit.oak.spi.commit.CommitHook;
+import org.apache.jackrabbit.oak.spi.commit.CommitInfo;
+import org.apache.jackrabbit.oak.spi.state.NodeState;
+import org.jetbrains.annotations.NotNull;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+import static com.google.common.base.Preconditions.checkNotNull;
+
+/**
+ * A commit hook that measures the time it took to process the commit. This
+ * hook only reports timing for successfully processed commits. Those that fail
+ * with a {@link CommitFailedException} are not reported.
+ */
+class TimingHook implements CommitHook {
+
+ private static final Logger LOG =
LoggerFactory.getLogger(TimingHook.class);
+
+ private final CommitHook hook;
+ private final Listener listener;
+
+ static CommitHook wrap(CommitHook hook, Listener listener) {
+ return new TimingHook(hook, listener);
+ }
+
+ private TimingHook(@NotNull CommitHook hook,
+ @NotNull Listener listener) {
+ this.hook = checkNotNull(hook);
+ this.listener = checkNotNull(listener);
+ }
+
+ @Override
+ public @NotNull NodeState processCommit(NodeState before,
+ NodeState after,
+ CommitInfo info)
+ throws CommitFailedException {
+ long start = System.nanoTime();
+ NodeState state = hook.processCommit(before, after, info);
+ processed(System.nanoTime() - start);
+ return state;
+ }
+
+ private void processed(long timeNano) {
+ try {
+ listener.processed(timeNano, TimeUnit.NANOSECONDS);
+ } catch (Throwable t) {
+ LOG.warn("Listener failed with exception", t);
+ }
+ }
+
+ interface Listener {
+
+ void processed(long time, TimeUnit unit);
+ }
+}
Propchange:
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/TimingHook.java
------------------------------------------------------------------------------
svn:eol-style = native
Modified:
jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreStatsCollectorIT.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreStatsCollectorIT.java?rev=1851392&r1=1851391&r2=1851392&view=diff
==============================================================================
---
jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreStatsCollectorIT.java
(original)
+++
jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreStatsCollectorIT.java
Tue Jan 15 16:11:49 2019
@@ -97,7 +97,7 @@ public class DocumentNodeStoreStatsColle
NodeBuilder nb = nodeStore.getRoot().builder();
nb.child("a");
nodeStore.merge(nb, EmptyHook.INSTANCE, CommitInfo.EMPTY);
- verify(statsCollector).doneMerge(eq(0), anyLong(), eq(false),
eq(false));
+ verify(statsCollector).doneMerge(eq(0), anyLong(), eq(0L), eq(false));
}
@Test
@@ -122,10 +122,10 @@ public class DocumentNodeStoreStatsColle
}
- verify(statsCollector).failedMerge(anyInt(), anyLong(), eq(false),
eq(false));
+ verify(statsCollector).failedMerge(anyInt(), anyLong(), eq(0L),
eq(false));
//Should be called once more with exclusive lock
- verify(statsCollector).failedMerge(anyInt(), anyLong(), eq(false),
eq(true));
+ verify(statsCollector).failedMerge(anyInt(), anyLong(), eq(0L),
eq(true));
}
@Test
@@ -179,4 +179,47 @@ public class DocumentNodeStoreStatsColle
&& stats.externalChangesLag - lag < 100
));
}
+
+ @Test
+ public void waitUntilHead() throws Exception {
+ NodeBuilder nb = nodeStore.getRoot().builder();
+ nb.child("a");
+ nodeStore.merge(nb, EmptyHook.INSTANCE, CommitInfo.EMPTY);
+ verify(statsCollector).doneWaitUntilHead(eq(0L));
+ }
+
+ @Test
+ public void mergeLockAcquired() throws Exception {
+ NodeBuilder nb = nodeStore.getRoot().builder();
+ nb.child("a");
+ nodeStore.merge(nb, EmptyHook.INSTANCE, CommitInfo.EMPTY);
+ verify(statsCollector).doneMergeLockAcquired(anyLong());
+ }
+
+ @Test
+ public void commitHookProcessed() throws Exception {
+ NodeBuilder nb = nodeStore.getRoot().builder();
+ nb.child("a");
+ nodeStore.merge(nb, EmptyHook.INSTANCE, CommitInfo.EMPTY);
+ verify(statsCollector).doneCommitHookProcessed(anyLong());
+ }
+
+ @Test
+ public void commitHookProcessedOnBranch() throws Exception {
+ NodeBuilder nb = nodeStore.getRoot().builder();
+ nb.child("a");
+ TestUtils.persistToBranch(nb);
+ nb.child("b");
+ nodeStore.merge(nb, EmptyHook.INSTANCE, CommitInfo.EMPTY);
+ verify(statsCollector).doneCommitHookProcessed(anyLong());
+ }
+
+ @Test
+ public void changesApplied() throws Exception {
+ Mockito.reset(statsCollector);
+ NodeBuilder nb = nodeStore.getRoot().builder();
+ nb.child("a");
+ nodeStore.merge(nb, EmptyHook.INSTANCE, CommitInfo.EMPTY);
+ verify(statsCollector).doneChangesApplied(anyLong());
+ }
}
\ No newline at end of file
Added:
jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/TimingHookTest.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/TimingHookTest.java?rev=1851392&view=auto
==============================================================================
---
jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/TimingHookTest.java
(added)
+++
jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/TimingHookTest.java
Tue Jan 15 16:11:49 2019
@@ -0,0 +1,54 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.apache.jackrabbit.oak.plugins.document;
+
+import java.util.concurrent.atomic.AtomicLong;
+
+import org.apache.jackrabbit.oak.api.CommitFailedException;
+import org.apache.jackrabbit.oak.spi.commit.CommitInfo;
+import org.apache.jackrabbit.oak.spi.state.NodeState;
+import org.jetbrains.annotations.NotNull;
+import org.junit.Test;
+
+import static
org.apache.jackrabbit.oak.plugins.memory.EmptyNodeState.EMPTY_NODE;
+import static org.hamcrest.Matchers.greaterThanOrEqualTo;
+import static org.junit.Assert.assertThat;
+
+public class TimingHookTest {
+
+ private static long DELAY_MS = 10;
+
+ @Test
+ public void commitTime() throws CommitFailedException {
+ AtomicLong processingTime = new AtomicLong();
+ TimingHook.wrap(
+ (before, after, info) -> sleep(),
+ (time, unit) -> processingTime.set(unit.toMillis(time))
+ ).processCommit(EMPTY_NODE, EMPTY_NODE, CommitInfo.EMPTY);
+ assertThat(processingTime.get(), greaterThanOrEqualTo(DELAY_MS));
+ }
+
+ @NotNull
+ private NodeState sleep() {
+ try {
+ Thread.sleep(DELAY_MS);
+ } catch (InterruptedException e) {
+ // ignore
+ }
+ return EMPTY_NODE;
+ }
+}
Propchange:
jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/TimingHookTest.java
------------------------------------------------------------------------------
svn:eol-style = native
