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 ch...@apache.org on 2014/12/16 14:39:35 UTC
svn commit: r1645948 - in
/jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins:
document/DocumentNodeStore.java observation/EventGenerator.java
Author: chetanm
Date: Tue Dec 16 13:39:34 2014
New Revision: 1645948
URL: http://svn.apache.org/r1645948
Log:
OAK-2359 - diffImpl is inefficient when there are many split documents
Adding extra logging as per patch by Stefan
Modified:
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/observation/EventGenerator.java
Modified: jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java?rev=1645948&r1=1645947&r2=1645948&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java (original)
+++ jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java Tue Dec 16 13:39:34 2014
@@ -756,6 +756,7 @@ public final class DocumentNodeStore
String name, int limit) {
String path = parent.getPath();
Revision rev = parent.getLastRevision();
+ LOG.trace("Reading children for [{}] ast rev [{}]", path, rev);
Iterable<NodeDocument> docs;
DocumentNodeState.Children c = new DocumentNodeState.Children();
// add one to the requested limit for the raw limit
@@ -1650,17 +1651,28 @@ public final class DocumentNodeStore
// TODO this does not work well for large child node lists
// use a document store index instead
int max = MANY_CHILDREN_THRESHOLD;
+
+ final boolean debug = LOG.isDebugEnabled();
+ final long start = debug ? now() : 0;
+
DocumentNodeState.Children fromChildren, toChildren;
fromChildren = getChildren(from, null, max);
toChildren = getChildren(to, null, max);
+
+ final long getChildrenDoneIn = debug ? now() : 0;
+
+ String diffAlgo;
if (!fromChildren.hasMore && !toChildren.hasMore) {
+ diffAlgo = "diffFewChildren";
diffFewChildren(w, from.getPath(), fromChildren,
from.getLastRevision(), toChildren, to.getLastRevision());
} else {
if (FAST_DIFF) {
+ diffAlgo = "diffManyChildren";
diffManyChildren(w, from.getPath(),
from.getLastRevision(), to.getLastRevision());
} else {
+ diffAlgo = "diffAllChildren";
max = Integer.MAX_VALUE;
fromChildren = getChildren(from, null, max);
toChildren = getChildren(to, null, max);
@@ -1668,6 +1680,13 @@ public final class DocumentNodeStore
from.getLastRevision(), toChildren, to.getLastRevision());
}
}
+
+ if (debug) {
+ long end = now();
+ LOG.debug("Diff performed via '{}' at [{}] between revisions [{}] => [{}] took {} ms ({} ms)",
+ diffAlgo, from.getPath(), from.getLastRevision(), to.getLastRevision(),
+ end - start, getChildrenDoneIn - start);
+ }
return w.toString();
}
@@ -1679,10 +1698,15 @@ public final class DocumentNodeStore
String fromKey = Utils.getKeyLowerLimit(path);
String toKey = Utils.getKeyUpperLimit(path);
Set<String> paths = Sets.newHashSet();
+
+ LOG.debug("diffManyChildren: path: {}, fromRev: {}, toRev: {}", path, fromRev, toRev);
+
for (NodeDocument doc : store.query(Collection.NODES, fromKey, toKey,
NodeDocument.MODIFIED_IN_SECS, minValue, Integer.MAX_VALUE)) {
paths.add(doc.getPath());
}
+
+ LOG.debug("diffManyChildren: Affected paths: {}", paths.size());
// also consider nodes with not yet stored modifications (OAK-1107)
Revision minRev = new Revision(minTimestamp, 0, getClusterId());
addPathsForDiff(path, paths, getPendingModifications().getPaths(minRev));
@@ -1698,6 +1722,9 @@ public final class DocumentNodeStore
DocumentNodeState fromNode = getNode(p, fromRev);
DocumentNodeState toNode = getNode(p, toRev);
String name = PathUtils.getName(p);
+
+ LOG.trace("diffManyChildren: Changed Path {}", path);
+
if (fromNode != null) {
// exists in fromRev
if (toNode != null) {
@@ -1785,6 +1812,10 @@ public final class DocumentNodeStore
return (DocumentRootBuilder) builder;
}
+ private static long now(){
+ return System.currentTimeMillis();
+ }
+
private void moveOrCopyNode(boolean move,
DocumentNodeState source,
String targetPath,
Modified: jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/observation/EventGenerator.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/observation/EventGenerator.java?rev=1645948&r1=1645947&r2=1645948&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/observation/EventGenerator.java (original)
+++ jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/observation/EventGenerator.java Tue Dec 16 13:39:34 2014
@@ -36,6 +36,8 @@ import javax.annotation.Nonnull;
import org.apache.jackrabbit.oak.api.PropertyState;
import org.apache.jackrabbit.oak.spi.state.NodeState;
import org.apache.jackrabbit.oak.spi.state.NodeStateDiff;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
/**
* Continuation-based content diff implementation that generates
@@ -53,6 +55,7 @@ import org.apache.jackrabbit.oak.spi.sta
* </pre>
*/
public class EventGenerator {
+ private static final Logger log = LoggerFactory.getLogger(EventGenerator.class);
/**
* Maximum number of content changes to process during the
@@ -68,7 +71,7 @@ public class EventGenerator {
*/
private static final int MAX_QUEUED_CONTINUATIONS = 1000;
- private final LinkedList<Runnable> continuations = newLinkedList();
+ private final LinkedList<Continuation> continuations = newLinkedList();
/**
* Creates a new generator instance. Changes to process need to be added
@@ -105,7 +108,15 @@ public class EventGenerator {
*/
public void generate() {
if (!continuations.isEmpty()) {
- continuations.removeFirst().run();
+ final Continuation c = continuations.removeFirst();
+ if (log.isDebugEnabled()) {
+ log.debug("Starting event generation ...");
+ long start = System.currentTimeMillis();
+ c.run();
+ log.debug("Generated {} events in {} ms", c.counter, (System.currentTimeMillis() - start));
+ } else {
+ c.run();
+ }
}
}