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 st...@apache.org on 2021/10/20 09:58:10 UTC
[jackrabbit-oak] branch trunk updated: OAK-9601 : added more
details to split gc, silencing prev-document-not-found warns somewhat (#394)
This is an automated email from the ASF dual-hosted git repository.
stefanegli pushed a commit to branch trunk
in repository https://gitbox.apache.org/repos/asf/jackrabbit-oak.git
The following commit(s) were added to refs/heads/trunk by this push:
new 24676c4 OAK-9601 : added more details to split gc, silencing prev-document-not-found warns somewhat (#394)
24676c4 is described below
commit 24676c41a8999b9b07ecb779280bdc9f2613d846
Author: stefan-egli <st...@apache.org>
AuthorDate: Wed Oct 20 11:58:03 2021 +0200
OAK-9601 : added more details to split gc, silencing prev-document-not-found warns somewhat (#394)
* OAK-9601 : added more details to split gc, silencing prev-document-not-found warns somewhat
* OAK-9601 : removed unused import
* OAK-9601 : default was meant to be 15min, not 15sec
* OAK-9601 : still logging to debug in case of logSilencing
* OAK-9601 : minor rewording
* OAK-9601 : minor log adjustment
---
.../oak/plugins/document/NodeDocument.java | 17 +++-
.../oak/plugins/document/SplitDocumentCleanUp.java | 19 +++-
.../oak/plugins/document/util/LogSilencer.java | 109 +++++++++++++++++++++
.../oak/plugins/document/util/LogSilencerTest.java | 96 ++++++++++++++++++
4 files changed, 238 insertions(+), 3 deletions(-)
diff --git a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/NodeDocument.java b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/NodeDocument.java
index e22ac1d..40fe430 100644
--- a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/NodeDocument.java
+++ b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/NodeDocument.java
@@ -47,6 +47,7 @@ import org.apache.jackrabbit.oak.commons.json.JsopReader;
import org.apache.jackrabbit.oak.commons.json.JsopTokenizer;
import org.apache.jackrabbit.oak.commons.json.JsopWriter;
import org.apache.jackrabbit.oak.plugins.document.memory.MemoryDocumentStore;
+import org.apache.jackrabbit.oak.plugins.document.util.LogSilencer;
import org.apache.jackrabbit.oak.plugins.document.util.Utils;
import org.jetbrains.annotations.NotNull;
import org.jetbrains.annotations.Nullable;
@@ -87,6 +88,8 @@ public final class NodeDocument extends Document {
static final Logger LOG = LoggerFactory.getLogger(NodeDocument.class);
+ private static final LogSilencer LOG_SILENCER = new LogSilencer();
+
/**
* All NodeDocument ID value would be greater than this value
* It can be used as startKey in DocumentStore#query methods
@@ -1877,7 +1880,13 @@ public final class NodeDocument extends Document {
//----------------------------< internal >----------------------------------
private void previousDocumentNotFound(String prevId, Revision rev) {
- LOG.warn("Document with previous revisions not found: " + prevId);
+ final boolean logSilence = LOG_SILENCER.silence(prevId);
+ if (!logSilence) {
+ LOG.warn("Document with previous revisions not found: " + prevId
+ + LogSilencer.SILENCING_POSTFIX);
+ } else {
+ LOG.debug("Document with previous revisions not found: {}", prevId);
+ }
// main document may be stale, evict it from the cache if it is
// older than one minute. We don't want to invalidate a document
// too frequently if the document structure is really broken.
@@ -1887,7 +1896,11 @@ public final class NodeDocument extends Document {
long now = Revision.getCurrentTimestamp();
while (doc != null
&& doc.getCreated() + TimeUnit.MINUTES.toMillis(1) < now) {
- LOG.info("Invalidated cached document {}", id);
+ if (!logSilence) {
+ LOG.info("Invalidated cached document {} -{}", id, LogSilencer.SILENCING_POSTFIX);
+ } else {
+ LOG.debug("Invalidated cached document {}", id);
+ }
store.invalidateCache(NODES, id);
// also invalidate intermediate docs if there are any matching
Iterable<Range> ranges = doc.getPreviousRanges().values();
diff --git a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/SplitDocumentCleanUp.java b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/SplitDocumentCleanUp.java
index 14c5766..ac38225 100644
--- a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/SplitDocumentCleanUp.java
+++ b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/SplitDocumentCleanUp.java
@@ -23,6 +23,7 @@ import java.util.List;
import com.google.common.collect.Lists;
import org.apache.jackrabbit.oak.plugins.document.VersionGarbageCollector.VersionGCStats;
+import org.apache.jackrabbit.oak.plugins.document.util.LogSilencer;
import org.apache.jackrabbit.oak.plugins.document.util.Utils;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
@@ -39,6 +40,8 @@ public class SplitDocumentCleanUp implements Closeable {
private static final Logger LOG = LoggerFactory.getLogger(SplitDocumentCleanUp.class);
+ private static final LogSilencer LOG_SILENCER = new LogSilencer();
+
// number of document IDs to collect before removing them in a single call
private static final int DELETE_BATCH_SIZE = 100;
@@ -136,7 +139,8 @@ public class SplitDocumentCleanUp implements Closeable {
checkArgument(splitDoc.getSplitDocType() == INTERMEDIATE,
"Illegal type: %s", splitDoc.getSplitDocType());
- UpdateOp update = new UpdateOp(splitDoc.getId(), false);
+ String splitDocId = splitDoc.getId();
+ UpdateOp update = new UpdateOp(splitDocId, false);
NodeDocument.removePrevious(update, rev);
NodeDocument old = store.findAndUpdate(NODES, update);
if (old != null
@@ -146,6 +150,19 @@ public class SplitDocumentCleanUp implements Closeable {
disconnect(old);
removeFromDocumentStore(old.getId());
stats.intermediateSplitDocGCCount++;
+ } else if (old == null) {
+ // OAK-9601 : suspected root cause: if the "previous" entry
+ // could not be removed (tbd, maybe modCnt mismatch, race condition etc),
+ // it would not properly have done the disconnect()
+ // and perhaps that is why we get these
+ // "Document with previous revisions not found"
+ if (!LOG_SILENCER.silence(splitDocId)) {
+ LOG.warn("Split document reference could not be removed from intermediate {} -{}",
+ splitDocId, LogSilencer.SILENCING_POSTFIX);
+ } else {
+ LOG.debug("Split document reference could not be removed from intermediate {}",
+ splitDocId);
+ }
}
}
diff --git a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/util/LogSilencer.java b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/util/LogSilencer.java
new file mode 100644
index 0000000..bf38704
--- /dev/null
+++ b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/util/LogSilencer.java
@@ -0,0 +1,109 @@
+/*
+ * 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.util;
+
+import java.time.Duration;
+import java.util.Collections;
+import java.util.LinkedHashMap;
+import java.util.Map;
+
+/**
+ * Utility class to silence log output based on a specific key.
+ * <p>
+ * The key, together with the timeout, will be put into a small LRU cache
+ * and later used to determine silencing or not.
+ */
+public class LogSilencer {
+
+ public static final String SILENCING_POSTFIX = " (similar log silenced for a while)";
+ private static final long DEFAULT_SILENCE_MILLIS = Duration.ofMinutes(15).toMillis();
+ private static final int DEFAULT_CACHE_SIZE = 64;
+ private final int cacheSize;
+ private final long silenceMillis;
+
+ @SuppressWarnings("serial")
+ private final Map<String, Long> silences = Collections.synchronizedMap(
+ new LinkedHashMap<String, Long>() {
+
+ protected final boolean removeEldestEntry(Map.Entry<String, Long> eldest) {
+ return size() > cacheSize;
+ }
+ });
+
+ public LogSilencer() {
+ this(DEFAULT_SILENCE_MILLIS, DEFAULT_CACHE_SIZE);
+ }
+
+ /**
+ * Create a new LogSilencer
+ * @param silenceMillis milliseconds after which the silences herein should time out.
+ * If the value is <0 it means no timeout, if it is ==0 it is silenced only
+ * for the very same millisecond, and >0 the silence is active for that specified
+ * amount of time.
+ * @param cacheSize the size of the cache held by the LogSilencer. The cache is
+ * used to store the keys and timeout values for each of them.
+ */
+ public LogSilencer(long silenceMillis, int cacheSize) {
+ if (cacheSize <= 0) {
+ throw new IllegalArgumentException("cacheSize must be > 0, is: " + cacheSize);
+ }
+ this.silenceMillis = silenceMillis;
+ this.cacheSize = cacheSize;
+ }
+
+ /**
+ * Determine whether based on a provided key logging about that key should be silenced.
+ * <p>
+ * The actual scope and context of the provided key is entirely up to the caller
+ * and not relevant for the LogSilencer. All the LogSilencer is trying to do
+ * is to provide a mechanism to "silence based on a key"
+ * @param key a key within the caller's context which identified some log
+ * @return whether a silence for the provided key is in place or not.
+ * The silence times out after a certain, configurable amount of time.
+ */
+ public final boolean silence(String key) {
+ // this is only "approximately now", since we only get the timestamp
+ // at the beginning of this method and don't repeat that further down.
+ // hence the time used within this method we approximate away - hence 'approxNow'.
+ final Long approxNow = System.currentTimeMillis();
+ final Long prevOrNull = silences.putIfAbsent(key, approxNow);
+ if (prevOrNull == null) {
+ // then we did not have this key in the silences map
+ // which means no silence yet
+ return false;
+ } else {
+ // otherwise we did have this key already in the silence,
+ // let's compare the time for silence-timeout
+ if (silenceMillis < 0) {
+ // that means there is no timeout, ever.
+ // so we silence
+ return true;
+ } else if (approxNow <= prevOrNull + silenceMillis) {
+ // note that 'silenceMillis' can be 0
+ // in which case the silence is only applied in the very same millisecond.
+ return true;
+ }
+ // otherwise the silence expired, so we have to re-add it.
+ // concurrency note : if another thread comes in between,
+ // it should not do any harm, since both will race to
+ // put the 'approxNow' into the cache - and more or less
+ // both will have a similar value for 'approxNow'
+ silences.put(key, approxNow);
+ return false;
+ }
+ }
+}
diff --git a/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/util/LogSilencerTest.java b/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/util/LogSilencerTest.java
new file mode 100644
index 0000000..4502031
--- /dev/null
+++ b/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/util/LogSilencerTest.java
@@ -0,0 +1,96 @@
+/*
+ * 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.util;
+
+import static org.junit.Assert.assertFalse;
+import static org.junit.Assert.assertTrue;
+import static org.junit.Assert.fail;
+
+import java.util.UUID;
+
+import org.junit.Test;
+
+public class LogSilencerTest {
+
+ @Test
+ public void testBoundaries() throws Exception {
+ try {
+ new LogSilencer(-1, 0);
+ fail("<= 0 as cacheSize is not allowed");
+ } catch(Exception e) {
+ // ok
+ }
+ try {
+ new LogSilencer(-1, -1);
+ fail("<= 0 as cacheSize is not allowed");
+ } catch(Exception e) {
+ // ok
+ }
+ LogSilencer l = new LogSilencer();
+ assertFalse(l.silence(null));
+ assertTrue(l.silence(null));
+ }
+
+ private void assertNotSilencedWithRandomKeys(LogSilencer l) {
+ for(int i = 0; i < 1000; i++) {
+ final String uuid = UUID.randomUUID().toString();
+ assertFalse(l.silence(uuid));
+ assertTrue(l.silence(uuid));
+ }
+ }
+
+ @Test
+ public void testCacheSize1() throws Exception {
+ final LogSilencer l = new LogSilencer(-1, 1);
+ assertNotSilencedWithRandomKeys(l);
+ for(int i = 0; i < 1000; i++) {
+ assertFalse(l.silence("foo" + i));
+ assertTrue(l.silence("foo" + i));
+ assertTrue(l.silence("foo" + i));
+ }
+ }
+
+ @Test
+ public void testCacheSize2() throws Exception {
+ final LogSilencer l = new LogSilencer(-1, 2);
+ assertNotSilencedWithRandomKeys(l);
+ for(int i = 0; i < 1000; i++) {
+ assertFalse(l.silence("foo" + (2 * i)));
+ assertFalse(l.silence("foo" + (2 * i + 1)));
+ assertTrue(l.silence("foo" + (2 * i)));
+ assertTrue(l.silence("foo" + (2 * i + 1)));
+ assertTrue(l.silence("foo" + (2 * i)));
+ assertTrue(l.silence("foo" + (2 * i + 1)));
+ }
+ }
+
+ @Test
+ public void testCacheSize10() throws Exception {
+ final LogSilencer l = new LogSilencer(-1, 10);
+ assertNotSilencedWithRandomKeys(l);
+ }
+
+ @Test
+ public void testTimeout() throws Exception {
+ final LogSilencer l = new LogSilencer(100, 10);
+ assertFalse(l.silence("foo"));
+ assertTrue(l.silence("foo"));
+ Thread.sleep(150);
+ assertFalse(l.silence("foo"));
+ assertTrue(l.silence("foo"));
+ }
+}