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 2016/06/08 13:17:25 UTC
svn commit: r1747392 - in /jackrabbit/oak/trunk/oak-segment-tar: pom.xml
src/main/java/org/apache/jackrabbit/oak/segment/SegmentWriter.java
Author: mduerig
Date: Wed Jun 8 13:17:25 2016
New Revision: 1747392
URL: http://svn.apache.org/viewvc?rev=1747392&view=rev
Log:
OAK-4445: Collect write statistics (WIP)
Logging initial statistics
Modified:
jackrabbit/oak/trunk/oak-segment-tar/pom.xml
jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/SegmentWriter.java
Modified: jackrabbit/oak/trunk/oak-segment-tar/pom.xml
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-segment-tar/pom.xml?rev=1747392&r1=1747391&r2=1747392&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-segment-tar/pom.xml (original)
+++ jackrabbit/oak/trunk/oak-segment-tar/pom.xml Wed Jun 8 13:17:25 2016
@@ -124,6 +124,11 @@
<version>2.4</version>
</dependency>
<dependency>
+ <groupId>org.apache.commons</groupId>
+ <artifactId>commons-math</artifactId>
+ <version>2.2</version>
+ </dependency>
+ <dependency>
<groupId>com.google.guava</groupId>
<artifactId>guava</artifactId>
</dependency>
Modified: jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/SegmentWriter.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/SegmentWriter.java?rev=1747392&r1=1747391&r2=1747392&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/SegmentWriter.java (original)
+++ jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/SegmentWriter.java Wed Jun 8 13:17:25 2016
@@ -60,6 +60,7 @@ import javax.jcr.PropertyType;
import com.google.common.base.Supplier;
import com.google.common.base.Suppliers;
import com.google.common.io.Closeables;
+import org.apache.commons.math.stat.descriptive.SynchronizedDescriptiveStatistics;
import org.apache.jackrabbit.oak.api.Blob;
import org.apache.jackrabbit.oak.api.PropertyState;
import org.apache.jackrabbit.oak.api.Type;
@@ -261,7 +262,8 @@ public class SegmentWriter {
RecordId nodeId = writeOperationHandler.execute(new SegmentWriteOperation() {
@Override
public RecordId execute(SegmentBufferWriter writer) throws IOException {
- return with(writer).writeNode(state, 0);
+ return new CompactionStats(writeNodeStats, compactNodeStats, false)
+ .writeNode(this, writer, state);
}
});
return new SegmentNodeState(reader, this, nodeId);
@@ -287,7 +289,8 @@ public class SegmentWriter {
RecordId nodeId = writeOperationHandler.execute(new SegmentWriteOperation(cancel) {
@Override
public RecordId execute(SegmentBufferWriter writer) throws IOException {
- return with(writer).writeNode(state, 0);
+ return new CompactionStats(writeNodeStats, compactNodeStats, true)
+ .writeNode(this, writer, state);
}
});
writeOperationHandler.flush();
@@ -297,6 +300,112 @@ public class SegmentWriter {
}
}
+ private final SynchronizedDescriptiveStatistics writeNodeStats = new SynchronizedDescriptiveStatistics();
+ private final SynchronizedDescriptiveStatistics compactNodeStats = new SynchronizedDescriptiveStatistics();
+
+ // FIXME OAK-4445: Collect write statistics: clean this up:
+ // - It should be possible to switch the statistics on/off. There should be no
+ // performance penalty when off.
+ // - Expose via logging and/or MBean?
+ // - What metrics should we collect? Use the Metrics API!?
+ // - Decouple this from the SegmentWriter
+ private static class CompactionStats {
+ @Nonnull
+ private final SynchronizedDescriptiveStatistics writeNodeStats;
+ @Nonnull
+ private final SynchronizedDescriptiveStatistics compactNodeStats;
+
+ /*
+ * {@code true} iff this is an explicit compaction (vs. an implicit
+ * and deferred one triggered by a commit referring to an "old" base
+ * state.
+ */
+ private final boolean isCompaction;
+
+ /*
+ * Total number of nodes in the subtree rooted at the node passed
+ * to {@link #writeNode(SegmentWriteOperation, SegmentBufferWriter, NodeState)}
+ */
+ public int nodeCount;
+
+ /*
+ * Number of cache hits for a deferred compacted node
+ */
+ public int cacheHits;
+
+ /*
+ * Number of cache misses for a deferred compacted node
+ */
+ public int cacheMiss;
+
+ /*
+ * Number of nodes that where de-duplicated as the store already contained
+ * them.
+ */
+ public int deDupNodes;
+
+ /*
+ * Number of nodes that actually had to be written as there was no de-duplication
+ * and a cache miss (in case of a deferred compaction).
+ */
+ public int writesOps;
+
+ public CompactionStats(
+ @Nonnull SynchronizedDescriptiveStatistics writeNodeStats,
+ @Nonnull SynchronizedDescriptiveStatistics compactNodeStats,
+ boolean isCompaction) {
+ this.writeNodeStats = writeNodeStats;
+ this.compactNodeStats = compactNodeStats;
+ this.isCompaction = isCompaction;
+ }
+
+ /*
+ * The operation caused a deferred compaction iff it accessed the cache.
+ */
+ public boolean isDeferredCompactionOp() {
+ return cacheHits + cacheMiss > 0;
+ }
+
+ @Nonnull
+ public RecordId writeNode(
+ @Nonnull SegmentWriteOperation op,
+ @Nonnull SegmentBufferWriter writer,
+ @Nonnull NodeState state)
+ throws IOException {
+ long t = System.nanoTime();
+ try {
+ return op.with(writer).with(this).writeNode(state, 0);
+ } finally {
+ if (isCompaction) {
+ LOG.info("Write node stats: {}", writeNodeStats);
+ LOG.info("Compact node stats: {}", compactNodeStats);
+ writeNodeStats.clear();
+ compactNodeStats.clear();
+ } else {
+ if (isDeferredCompactionOp()) {
+ compactNodeStats.addValue(System.nanoTime() - t);
+ LOG.info(toString());
+ } else {
+ writeNodeStats.addValue(System.nanoTime() - t);
+ }
+ }
+ }
+ }
+
+ @Override
+ public String toString() {
+ return "NodeStats{" +
+ "op=" + (isDeferredCompactionOp() ? "compact" : "write") +
+ ", nodeCount=" + nodeCount +
+ ", writeOps=" + writesOps +
+ ", deDupNodes=" + deDupNodes +
+ ", cacheHits=" + cacheHits +
+ ", cacheMiss=" + cacheMiss +
+ ", hitRate=" + (100*(double) cacheHits / ((double) cacheHits + (double) cacheMiss)) +
+ '}';
+ }
+ }
+
/**
* This {@code WriteOperation} implementation is used internally to provide
* context to a recursive chain of calls without having pass the context
@@ -316,6 +425,10 @@ public class SegmentWriter {
}
private final Supplier<Boolean> cancel;
+
+ @CheckForNull
+ private CompactionStats compactionStats;
+
private SegmentBufferWriter writer;
private RecordCache<String> stringCache;
private RecordCache<Template> templateCache;
@@ -342,6 +455,12 @@ public class SegmentWriter {
return this;
}
+ @Nonnull
+ SegmentWriteOperation with(@Nonnull CompactionStats compactionStats) {
+ this.compactionStats = compactionStats;
+ return this;
+ }
+
private RecordId writeMap(@Nullable MapRecord base,
@Nonnull Map<String, RecordId> changes)
throws IOException {
@@ -851,6 +970,8 @@ public class SegmentWriter {
// Poor man's Either Monad
throw new CancelledWriteException();
}
+ assert compactionStats != null;
+ compactionStats.nodeCount++;
if (state instanceof SegmentNodeState) {
SegmentNodeState sns = ((SegmentNodeState) state);
if (sameStore(sns)) {
@@ -859,16 +980,21 @@ public class SegmentWriter {
if (isOldGeneration(sns.getRecordId())) {
RecordId cachedId = nodeCache.get(sns.getStableId());
if (cachedId != null) {
+ compactionStats.cacheHits++;
return cachedId;
+ } else {
+ compactionStats.cacheMiss++;
}
} else {
// This segment node state is already in this store,
// no need to write it again,
+ compactionStats.deDupNodes++;
return sns.getRecordId();
}
}
}
+ compactionStats.writesOps++;
RecordId recordId = writeNodeUncached(state, depth);
if (state instanceof SegmentNodeState) {
// This node state has been rewritten because it is from an older