Author: reschke
Date: Wed Apr 24 14:19:54 2019
New Revision: 1858053
URL: http://svn.apache.org/viewvc?rev=1858053&view=rev
Log:
OAK-8257: RDBDocumentStore: improve trace logging of batch operations
Modified:
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStore.java
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStoreJDBC.java
jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/MultiDocumentStoreTest.java
Modified:
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStore.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStore.java?rev=1858053&r1=1858052&r2=1858053&view=diff
==============================================================================
---
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStore.java
(original)
+++
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStore.java
Wed Apr 24 14:19:54 2019
@@ -429,10 +429,10 @@ public class RDBDocumentStore implements
UpdateOp conflictedOp = operationsToCover.remove(updateOp.getId());
if (conflictedOp != null) {
if (collection == Collection.NODES) {
- LOG.debug("update conflict on {}, invalidating cache and
retrying...", updateOp.getId());
+ LOG.debug("createOrUpdate: update conflict on {},
invalidating cache and retrying...", updateOp.getId());
nodesCache.invalidate(updateOp.getId());
} else {
- LOG.debug("update conflict on {}, retrying...",
updateOp.getId());
+ LOG.debug("createOrUpdate: update conflict on {},
retrying...", updateOp.getId());
}
results.put(conflictedOp, createOrUpdate(collection,
updateOp));
} else if (duplicates.contains(updateOp)) {
@@ -524,7 +524,16 @@ public class RDBDocumentStore implements
missingDocs.add(op.getId());
}
}
- oldDocs.putAll(readDocumentsUncached(collection, missingDocs));
+
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("bulkUpdate: cached docs to be updated: {}",
dumpKeysAndModcounts(oldDocs));
+ }
+
+ Map<String, T> freshDocs = readDocumentsUncached(collection,
missingDocs);
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("bulkUpdate: fresh docs to be updated: {}",
dumpKeysAndModcounts(freshDocs));
+ }
+ oldDocs.putAll(freshDocs);
try (CacheChangesTracker tracker = obtainTracker(collection,
Sets.union(oldDocs.keySet(), missingDocs) )) {
List<T> docsToUpdate = new ArrayList<T>(updates.size());
@@ -554,6 +563,10 @@ public class RDBDocumentStore implements
Set<String> failedUpdates = Sets.difference(keysToUpdate,
successfulUpdates);
oldDocs.keySet().removeAll(failedUpdates);
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("bulkUpdate: success for {}, failure for {}",
successfulUpdates, failedUpdates);
+ }
+
if (collection == Collection.NODES) {
List<NodeDocument> docsToCache = new ArrayList<>();
for (T doc : docsToUpdate) {
@@ -2294,6 +2307,23 @@ public class RDBDocumentStore implements
}
}
+ @NotNull
+ private static <T extends Document> String
dumpKeysAndModcounts(Map<String, T> docs) {
+ if (docs.isEmpty()) {
+ return "-";
+ } else {
+ StringBuilder sb = new StringBuilder();
+ for (Map.Entry<String, T> e : docs.entrySet()) {
+ Long mc = e.getValue().getModCount();
+ if (sb.length() != 0) {
+ sb.append(", ");
+ }
+ sb.append(String.format("%s (%s)", e.getKey(), mc == null ? ""
: mc.toString()));
+ }
+ return sb.toString();
+ }
+ }
+
// keeping track of CLUSTER_NODES updates
private Map<String, Long> cnUpdates = new ConcurrentHashMap<String,
Long>();
Modified:
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStoreJDBC.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStoreJDBC.java?rev=1858053&r1=1858052&r2=1858053&view=diff
==============================================================================
---
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStoreJDBC.java
(original)
+++
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStoreJDBC.java
Wed Apr 24 14:19:54 2019
@@ -333,6 +333,7 @@ public class RDBDocumentStoreJDBC {
Set<String> successfulUpdates = new HashSet<String>();
List<String> updatedKeys = new ArrayList<String>();
+ List<Long> modCounts = LOG.isTraceEnabled() ? new ArrayList<>() : null;
int[] batchResults = new int[0];
PreparedStatement stmt = connection.prepareStatement("update " +
tmd.getName()
@@ -372,6 +373,9 @@ public class RDBDocumentStoreJDBC {
stmt.setObject(si++, modcount - 1, Types.BIGINT);
stmt.addBatch();
updatedKeys.add(document.getId());
+ if (modCounts != null) {
+ modCounts.add(modcount);
+ }
batchIsEmpty = false;
}
@@ -386,6 +390,20 @@ public class RDBDocumentStoreJDBC {
stmt.close();
}
+ if (!updatedKeys.isEmpty() && LOG.isTraceEnabled()) {
+ StringBuilder br = new StringBuilder(String.format("update: batch
result on '%s' (sent: %d, received: %d):", tmd.getName(),
+ updatedKeys.size(), batchResults.length));
+ String delim = " ";
+ for (int i = 0; i < batchResults.length; i++) {
+ br.append(delim).append(batchResults[i]);
+ if (i < updatedKeys.size()) {
+ br.append(String.format(" (for %s (%d))",
updatedKeys.get(i), modCounts.get(i) - 1));
+ }
+ delim = ", ";
+ }
+ LOG.trace(br.toString());
+ }
+
for (int i = 0; i < batchResults.length; i++) {
int result = batchResults[i];
if (result == 1 || result == Statement.SUCCESS_NO_INFO) {
Modified:
jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/MultiDocumentStoreTest.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/MultiDocumentStoreTest.java?rev=1858053&r1=1858052&r2=1858053&view=diff
==============================================================================
---
jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/MultiDocumentStoreTest.java
(original)
+++
jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/MultiDocumentStoreTest.java
Wed Apr 24 14:19:54 2019
@@ -17,10 +17,13 @@
package org.apache.jackrabbit.oak.plugins.document;
import static java.util.Collections.synchronizedList;
+import static org.apache.jackrabbit.oak.plugins.document.Collection.NODES;
+import static
org.apache.jackrabbit.oak.plugins.document.util.Utils.getIdFromPath;
import static org.junit.Assert.assertEquals;
import static org.junit.Assert.assertNotEquals;
import static org.junit.Assert.assertNotNull;
import static org.junit.Assert.assertNull;
+import static org.junit.Assert.assertTrue;
import static org.junit.Assert.fail;
import java.util.ArrayList;
@@ -29,8 +32,12 @@ import java.util.List;
import java.util.Map;
import java.util.concurrent.CountDownLatch;
+import org.apache.jackrabbit.oak.commons.junit.LogCustomizer;
+import org.apache.jackrabbit.oak.plugins.document.rdb.RDBDocumentStore;
+import org.apache.jackrabbit.oak.plugins.document.rdb.RDBDocumentStoreJDBC;
import org.apache.jackrabbit.oak.plugins.document.util.Utils;
import org.junit.Test;
+import org.slf4j.event.Level;
import com.google.common.collect.Lists;
import com.google.common.collect.Maps;
@@ -366,4 +373,59 @@ public class MultiDocumentStoreTest exte
}
}
}
+
+ @Test
+ public void testTraceLoggingForBulkUpdates() {
+ if (ds instanceof RDBDocumentStore) {
+ int count = 10;
+
+ List<UpdateOp> ops = new ArrayList<>();
+ for (int i = 0; i < count; i++) {
+ UpdateOp op = new UpdateOp(getIdFromPath("/bulktracelog-" +
i), true);
+ ops.add(op);
+ removeMe.add(op.getId());
+ }
+ ds.createOrUpdate(NODES, ops);
+
+ LogCustomizer logCustomizerJDBC =
LogCustomizer.forLogger(RDBDocumentStoreJDBC.class.getName()).enable(Level.TRACE)
+ .matchesRegex("update: batch result.*").create();
+ logCustomizerJDBC.starting();
+ LogCustomizer logCustomizer =
LogCustomizer.forLogger(RDBDocumentStore.class.getName()).enable(Level.TRACE)
+ .matchesRegex("bulkUpdate: success.*").create();
+ logCustomizer.starting();
+
+ try {
+ ops.clear();
+
+ // modify first entry through secondary store
+ String modifiedRow = getIdFromPath("/bulktracelog-" + 0);
+ UpdateOp op2 = new UpdateOp(modifiedRow, false);
+ op2.set("foo", "bar");
+ ds2.createOrUpdate(NODES, op2);
+
+ // delete second entry through secondary store
+ String deletedRow = getIdFromPath("/bulktracelog-" + 1);
+ ds2.remove(NODES, deletedRow);
+
+ for (int i = 0; i < count; i++) {
+ UpdateOp op = new UpdateOp(getIdFromPath("/bulktracelog-"
+ i), false);
+ op.set("foo", "qux");
+ ops.add(op);
+ removeMe.add(op.getId());
+ }
+ ds.createOrUpdate(NODES, ops);
+
+ assertTrue(logCustomizer.getLogs().size() == 1);
+ assertTrue(logCustomizer.getLogs().get(0).contains("failure
for [" + modifiedRow + ", " + deletedRow + "]"));
+ // System.out.println(logCustomizer.getLogs());
+ assertTrue(logCustomizerJDBC.getLogs().size() == 1);
+ assertTrue(logCustomizerJDBC.getLogs().get(0).contains("0 (for
" + modifiedRow + " (1)"));
+ assertTrue(logCustomizerJDBC.getLogs().get(0).contains("0 (for
" + deletedRow + " (1)"));
+ // System.out.println(logCustomizerJDBC.getLogs());
+ } finally {
+ logCustomizer.finished();
+ logCustomizerJDBC.finished();
+ }
+ }
+ }
}
