This is an automated email from the ASF dual-hosted git repository.
joscorbe 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 d46ed91cf8 OAK-11997: Log slow Mongo queries in DocumentNodeStore
(#2596)
d46ed91cf8 is described below
commit d46ed91cf8c6c04e4d7679bda6fe955e48a66e9a
Author: José Andrés Cordero Benítez <[email protected]>
AuthorDate: Tue Oct 28 09:08:11 2025 +0100
OAK-11997: Log slow Mongo queries in DocumentNodeStore (#2596)
---
.../oak/plugins/document/Configuration.java | 8 +
.../plugins/document/DocumentNodeStoreService.java | 7 +
.../mongo/MongoDocumentNodeStoreBuilderBase.java | 19 ++
.../plugins/document/mongo/MongoDocumentStore.java | 67 ++++---
.../DocumentNodeStoreServiceConfigurationTest.java | 59 +++++++
.../mongo/MongoDocumentStoreQueryWarningTest.java | 196 +++++++++++++++++++++
6 files changed, 333 insertions(+), 23 deletions(-)
diff --git
a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/Configuration.java
b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/Configuration.java
index a23685f402..9e3d5d798d 100644
---
a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/Configuration.java
+++
b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/Configuration.java
@@ -39,6 +39,7 @@ import static
org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreServic
import static
org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreService.DEFAULT_FULL_GC_ENABLED;
import static
org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreService.DEFAULT_EMBEDDED_VERIFICATION_ENABLED;
import static
org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreService.DEFAULT_FULL_GC_GENERATION;
+import static
org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreService.DEFAULT_MONGO_QUERY_WARNING_THRESHOLD_MILLIS;
import static
org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreService.DEFAULT_PERFLOGGER_INFO_MILLIS;
import static
org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreService.DEFAULT_THROTTLING_ENABLED;
import static
org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreService.DEFAULT_FULL_GC_MODE;
@@ -516,4 +517,11 @@ import static
org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreServic
"merging the changes in case of a conflict. The Default
value is " + DEFAULT_AVOID_EXCLUSIVE_MERGE_LOCK +
" Note that this value can be overridden via framework
property 'oak.documentstore.avoidExclusiveMergeLock'")
boolean avoidExclusiveMergeLock() default
DEFAULT_AVOID_EXCLUSIVE_MERGE_LOCK;
+
+ @AttributeDefinition(
+ name = "MongoDB Query Warning Threshold (in millis)",
+ description = "Threshold in milliseconds for logging warnings when
MongoDB queries take longer than expected. " +
+ "A value of 0 disables query time warnings. Default is 0
(disabled). " +
+ "Note that this value can be overridden via framework
property 'oak.mongo.queryWarningThresholdMillis'")
+ long mongoQueryWarningThresholdMillis() default
DEFAULT_MONGO_QUERY_WARNING_THRESHOLD_MILLIS;
}
diff --git
a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreService.java
b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreService.java
index c263934da5..0426d7b2ae 100644
---
a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreService.java
+++
b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreService.java
@@ -231,6 +231,12 @@ public class DocumentNodeStoreService {
/** OAK-11246 : default millis for perflogger info */
static final long DEFAULT_PERFLOGGER_INFO_MILLIS = Long.MAX_VALUE;
+
+ /**
+ * Default threshold in milliseconds for logging MongoDB query warnings.
+ * A value of 0 disables query time warnings.
+ */
+ static final long DEFAULT_MONGO_QUERY_WARNING_THRESHOLD_MILLIS = 0;
/**
* Feature toggle name to enable the prev-no-prop cache.
@@ -392,6 +398,7 @@ public class DocumentNodeStoreService {
builder.setMongoWaitQueueTimeoutMillis(config.mongoWaitQueueTimeoutMillis());
builder.setMongoReadTimeoutMillis(config.mongoReadTimeoutMillis());
builder.setMongoMinHeartbeatFrequencyMillis(config.mongoMinHeartbeatFrequencyMillis());
+
builder.setMongoQueryWarningThresholdMillis(config.mongoQueryWarningThresholdMillis());
builder.setMongoDB(uri, db, config.blobCacheSize());
builder.setCollectionCompressionType(config.collectionCompressionType());
mkBuilder = builder;
diff --git
a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/mongo/MongoDocumentNodeStoreBuilderBase.java
b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/mongo/MongoDocumentNodeStoreBuilderBase.java
index fd0003c59e..73afe1e1ca 100644
---
a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/mongo/MongoDocumentNodeStoreBuilderBase.java
+++
b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/mongo/MongoDocumentNodeStoreBuilderBase.java
@@ -48,6 +48,7 @@ public abstract class MongoDocumentNodeStoreBuilderBase<T
extends MongoDocumentN
private MongoStatus mongoStatus;
private long maxReplicationLagMillis = TimeUnit.HOURS.toMillis(6);
private boolean clientSessionDisabled = false;
+ private long queryWarningThresholdMillis = 0;
private Integer leaseSocketTimeout;
private String uri;
private String name;
@@ -224,6 +225,24 @@ public abstract class MongoDocumentNodeStoreBuilderBase<T
extends MongoDocumentN
return thisBuilder();
}
+ /**
+ * Sets the threshold for logging warnings when MongoDB queries exceed
this duration.
+ *
+ * @param thresholdMillis the threshold in milliseconds. A value of 0
disables warnings.
+ * @return this builder.
+ */
+ public T setMongoQueryWarningThresholdMillis(long thresholdMillis) {
+ this.queryWarningThresholdMillis = thresholdMillis;
+ return thisBuilder();
+ }
+
+ /**
+ * @return the query warning threshold in milliseconds.
+ */
+ long getQueryWarningThresholdMillis() {
+ return queryWarningThresholdMillis;
+ }
+
/**
* @return the lease socket timeout in milliseconds. If none is set, then
* zero is returned.
diff --git
a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/mongo/MongoDocumentStore.java
b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/mongo/MongoDocumentStore.java
index a1a315ebed..51199f00e7 100644
---
a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/mongo/MongoDocumentStore.java
+++
b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/mongo/MongoDocumentStore.java
@@ -299,6 +299,12 @@ public class MongoDocumentStore implements DocumentStore {
private final boolean readOnly;
+ /**
+ * Threshold in milliseconds for logging MongoDB query warnings.
+ * A value of 0 disables query time warnings.
+ */
+ private final long queryWarningThresholdMillis;
+
@Override
public int getNodeNameLimit() {
return nodeNameLimit;
@@ -338,6 +344,7 @@ public class MongoDocumentStore implements DocumentStore {
initializeMongoStorageOptions(builder);
maxReplicationLagMillis = builder.getMaxReplicationLagMillis();
+ queryWarningThresholdMillis = builder.getQueryWarningThresholdMillis();
useClientSession = !builder.isClientSessionDisabled()
&&
Boolean.parseBoolean(System.getProperty("oak.mongo.clientSession", "true"));
@@ -407,7 +414,8 @@ public class MongoDocumentStore implements DocumentStore {
// reading documents in the nodes collection and checking
// existing indexes is performed against the MongoDB primary
// this ensures the information is up-to-date and accurate
- boolean emptyNodesCollection = execute(session ->
MongoUtils.isCollectionEmpty(nodes, session), Collection.NODES);
+ boolean emptyNodesCollection = execute(session ->
MongoUtils.isCollectionEmpty(nodes, session),
+ Collection.NODES, "isCollectionEmpty()");
createCollection(db, Collection.NODES.toString(), mongoStatus);
// compound index on _modified and _id
if (emptyNodesCollection) {
@@ -706,7 +714,7 @@ public class MongoDocumentStore implements DocumentStore {
dbCollection.find(getByKeyQuery(key)).into(result);
}
return null;
- }, collection);
+ }, collection, "findUncached(key=" + key + ")");
if(result.isEmpty()) {
docFound = false;
@@ -878,7 +886,8 @@ public class MongoDocumentStore implements DocumentStore {
}
}
return null;
- }, collection);
+ }, collection, "query(fromKey=" + fromKey + ", toKey=" + toKey +
+ ", indexedProperty=" + indexedProperty + ", limit=" + limit +
")");
resultSize = list.size();
if (cacheChangesTracker != null) {
@@ -916,7 +925,7 @@ public class MongoDocumentStore implements DocumentStore {
dbCollection.deleteOne(filter);
}
return null;
- }, collection);
+ }, collection, "remove(key=" + key + ")");
} catch (Exception e) {
throw DocumentStoreException.convert(e, "Remove failed for " +
key);
} finally {
@@ -941,7 +950,7 @@ public class MongoDocumentStore implements DocumentStore {
dbCollection.deleteMany(query);
}
return null;
- }, collection);
+ }, collection, "remove(keys batch, size=" +
keyBatch.size() + ")");
} catch (Exception e) {
throw DocumentStoreException.convert(e, "Remove failed for
" + keyBatch);
} finally {
@@ -985,7 +994,7 @@ public class MongoDocumentStore implements DocumentStore {
result = dbCollection.deleteMany(query);
}
return result.getDeletedCount();
- }, collection);
+ }, collection, "remove(query batch, size=" +
batch.size() + ")");
} catch (Exception e) {
throw DocumentStoreException.convert(e, "Remove failed
for " + batch);
} finally {
@@ -1025,7 +1034,8 @@ public class MongoDocumentStore implements DocumentStore {
result = dbCollection.deleteMany(query);
}
return result.getDeletedCount();
- }, collection), MAX_VALUE);
+ }, collection, "remove(indexedProperty=" + indexedProperty +
+ ", startValue=" + startValue + ", endValue=" + endValue +
")"), MAX_VALUE);
} catch (Exception e) {
throw DocumentStoreException.convert(e, "Remove failed for " +
collection + ": " +
indexedProperty + " in (" + startValue + ", " + endValue +
")");
@@ -1097,7 +1107,7 @@ public class MongoDocumentStore implements DocumentStore {
} else {
return dbCollection.updateOne(query, update);
}
- }, collection);
+ }, collection, "update(key=" + updateOp.getId() + ",
modCount=" + modCount + ")");
if (result.getModifiedCount() > 0) {
// success, update cached document
if (collection == Collection.NODES) {
@@ -1121,7 +1131,7 @@ public class MongoDocumentStore implements DocumentStore {
} else {
return dbCollection.findOneAndUpdate(query, update,
options);
}
- }, collection);
+ }, collection, "findAndModify(key=" + updateOp.getId() + ",
upsert=" + upsert + ")");
if (oldNode == null && upsert) {
newEntry = true;
@@ -1561,7 +1571,7 @@ public class MongoDocumentStore implements DocumentStore {
docs.put(foundDoc.getId(), foundDoc);
}
return null;
- }, collection);
+ }, collection, "find(keys, size=" + keys.size() + ")");
}
return docs;
} catch (BSONException ex) {
@@ -1596,7 +1606,7 @@ public class MongoDocumentStore implements DocumentStore {
docs.put(foundDoc.getId(), foundDoc);
}
return null;
- }, collection);
+ }, collection, "findDocumentsOneByOne(keys, size=" + keys.size() +
")");
}
return docs;
@@ -1638,7 +1648,7 @@ public class MongoDocumentStore implements DocumentStore {
} else {
return dbCollection.bulkWrite(writes, options);
}
- }, collection);
+ }, collection, "bulkUpdate(size=" + writes.size() + ")");
} catch (MongoBulkWriteException e) {
bulkResult = e.getWriteResult();
for (BulkWriteError err : e.getWriteErrors()) {
@@ -1723,7 +1733,7 @@ public class MongoDocumentStore implements DocumentStore {
dbCollection.insertMany(inserts);
}
return null;
- }, collection);
+ }, collection, "insertDocuments(size=" + inserts.size() + ")");
if (collection == Collection.NODES) {
for (T doc : docs) {
nodesCache.putIfAbsent((NodeDocument) doc);
@@ -1791,7 +1801,7 @@ public class MongoDocumentStore implements DocumentStore {
dbCollection.find(query).into(result);
}
return null;
- }, collection);
+ }, collection, "findCached(keys, size=" + keys.size() + ")");
List<T> docs = new ArrayList<>(keys.size());
for (BasicDBObject dbObject : result) {
@@ -2205,7 +2215,7 @@ public class MongoDocumentStore implements DocumentStore {
return doc;
}
- private Stopwatch startWatch() {
+ protected Stopwatch startWatch() {
return Stopwatch.createStarted();
}
@@ -2366,28 +2376,39 @@ public class MongoDocumentStore implements
DocumentStore {
}
/**
- * Execute a callable with an optional {@link ClientSession}. A client
- * session is passed to {@link DocumentStoreCallable#call(ClientSession)}
if
+ * Execute a callable with an optional {@link ClientSession} and track
execution time.
+ * A client session is passed to {@link
DocumentStoreCallable#call(ClientSession)} if
* the connected MongoDB servers support client sessions, otherwise the
* session is {@code null}. The client session must only be used within
* the scope of the {@link DocumentStoreCallable#call(ClientSession)}.
*
* @param callable the callable.
* @param collection the collection this callable operates on.
+ * @param description a description of the query for logging purposes.
* @param <T> the return type of the callable.
* @return the result of the callable.
* @throws DocumentStoreException if the callable throws an exception.
*/
private <T> T execute(@NotNull DocumentStoreCallable<T> callable,
- @NotNull Collection<?> collection)
+ @NotNull Collection<?> collection,
+ @NotNull String description)
throws DocumentStoreException {
+ final Stopwatch watch = startWatch();
T result;
- if (withClientSession()) {
- try (ClientSession session = createClientSession(collection)) {
- result = callable.call(session);
+ try {
+ if (withClientSession()) {
+ try (ClientSession session = createClientSession(collection)) {
+ result = callable.call(session);
+ }
+ } else {
+ result = callable.call(null);
+ }
+ } finally {
+ long durationMillis = watch.elapsed(TimeUnit.MILLISECONDS);
+ if (queryWarningThresholdMillis > 0 && durationMillis >
queryWarningThresholdMillis) {
+ LOG.warn("MongoDB query exceeded threshold: {} took {}ms on
collection {}",
+ description, durationMillis, collection);
}
- } else {
- result = callable.call(null);
}
return result;
}
diff --git
a/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreServiceConfigurationTest.java
b/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreServiceConfigurationTest.java
index 2dc014678e..4955d7fe92 100644
---
a/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreServiceConfigurationTest.java
+++
b/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreServiceConfigurationTest.java
@@ -468,6 +468,65 @@ public class DocumentNodeStoreServiceConfigurationTest {
assertEquals(15000, config.mongoHeartbeatFrequencyMillis());
}
+ @Test
+ public void mongoQueryWarningThresholdDefault() throws IOException {
+ Configuration config = createConfiguration();
+
+ // Verify default value is 0 (disabled)
+ assertEquals("Default query warning threshold should be 0 (disabled)",
+ 0L, config.mongoQueryWarningThresholdMillis());
+ }
+
+ @Test
+ public void mongoQueryWarningThresholdCustomValue() throws IOException {
+ // Set custom threshold value (30000 milliseconds = 30 seconds)
+ addConfigurationEntry(configuration,
"mongoQueryWarningThresholdMillis", 30000L);
+
+ Configuration config = createConfiguration();
+
+ // Verify the custom value is read correctly
+ assertEquals("Custom query warning threshold should be applied",
+ 30000L, config.mongoQueryWarningThresholdMillis());
+ }
+
+ @Test
+ public void mongoQueryWarningThresholdFromPreset() throws IOException {
+ // Set threshold value in preset (45000 milliseconds = 45 seconds)
+ addConfigurationEntry(preset, "mongoQueryWarningThresholdMillis",
45000L);
+
+ Configuration config = createConfiguration();
+
+ // Verify the preset value is read correctly
+ assertEquals("Query warning threshold from preset should be applied",
+ 45000L, config.mongoQueryWarningThresholdMillis());
+ }
+
+ @Test
+ public void mongoQueryWarningThresholdOverridePreset() throws IOException {
+ // Set threshold in both preset and configuration
+ // Configuration should take precedence
+ addConfigurationEntry(preset, "mongoQueryWarningThresholdMillis",
45000L);
+ addConfigurationEntry(configuration,
"mongoQueryWarningThresholdMillis", 60000L);
+
+ Configuration config = createConfiguration();
+
+ // Verify the configuration value overrides preset
+ assertEquals("Configuration should override preset for query warning
threshold",
+ 60000L, config.mongoQueryWarningThresholdMillis());
+ }
+
+ @Test
+ public void mongoQueryWarningThresholdDisabled() throws IOException {
+ // Explicitly set threshold to 0 to disable warnings
+ addConfigurationEntry(configuration,
"mongoQueryWarningThresholdMillis", 0L);
+
+ Configuration config = createConfiguration();
+
+ // Verify warnings are disabled
+ assertEquals("Query warning threshold of 0 should disable warnings",
+ 0L, config.mongoQueryWarningThresholdMillis());
+ }
+
private Configuration createConfiguration() throws IOException {
return DocumentNodeStoreServiceConfiguration.create(
context.componentContext(), configAdmin,
diff --git
a/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/mongo/MongoDocumentStoreQueryWarningTest.java
b/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/mongo/MongoDocumentStoreQueryWarningTest.java
new file mode 100644
index 0000000000..db55983559
--- /dev/null
+++
b/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/mongo/MongoDocumentStoreQueryWarningTest.java
@@ -0,0 +1,196 @@
+/*
+ * 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.mongo;
+
+import ch.qos.logback.classic.Level;
+import com.mongodb.client.MongoClient;
+import com.mongodb.client.MongoDatabase;
+import org.apache.jackrabbit.oak.commons.junit.LogCustomizer;
+import org.apache.jackrabbit.oak.commons.time.Stopwatch;
+import org.apache.jackrabbit.oak.plugins.document.Collection;
+import org.apache.jackrabbit.oak.plugins.document.MongoConnectionFactory;
+import org.apache.jackrabbit.oak.plugins.document.MongoUtils;
+import org.apache.jackrabbit.oak.plugins.document.util.MongoConnection;
+import org.junit.After;
+import org.junit.Assume;
+import org.junit.Before;
+import org.junit.BeforeClass;
+import org.junit.Rule;
+import org.junit.Test;
+
+import java.util.concurrent.TimeUnit;
+
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertTrue;
+
+/**
+ * Tests for MongoDB query warning threshold logging functionality.
+ */
+public class MongoDocumentStoreQueryWarningTest {
+
+ @Rule
+ public MongoConnectionFactory connectionFactory = new
MongoConnectionFactory();
+
+ private LogCustomizer logCustomizer;
+ private MongoConnection mongoConnection;
+ private TestStore store;
+
+ @BeforeClass
+ public static void checkMongoDbAvailable() {
+ Assume.assumeTrue(MongoUtils.isAvailable());
+ }
+
+ @Before
+ public void setUp() {
+ mongoConnection = connectionFactory.getConnection();
+ MongoUtils.dropCollections(mongoConnection.getDatabase());
+ logCustomizer = LogCustomizer
+ .forLogger(MongoDocumentStore.class)
+ .enable(Level.WARN)
+ .contains("MongoDB query exceeded threshold")
+ .create();
+ }
+
+ @After
+ public void tearDown() {
+ if (logCustomizer != null) {
+ logCustomizer.finished();
+ }
+ if (store != null) {
+ store.dispose();
+ store = null;
+ }
+ }
+
+ @Test
+ public void queryWarningDisabledByDefault() {
+ // Create store with default threshold (0 = disabled)
+ MongoDocumentNodeStoreBuilder builder = new
MongoDocumentNodeStoreBuilder();
+ store = new TestStore(mongoConnection.getMongoClient(),
+ mongoConnection.getDatabase(), builder, 0);
+
+ logCustomizer.starting();
+
+ // Perform query - even with mocked timing, no warning when threshold
is 0
+ store.find(Collection.NODES, "non-existing-key");
+
+ // No warning should be logged when threshold is 0
+ assertEquals("No warnings should be logged when threshold is 0",
+ 0, logCustomizer.getLogs().size());
+ }
+
+ @Test
+ public void queryWarningNotLoggedWhenBelowThreshold() {
+ // Create store with threshold of 20000 milliseconds (20 seconds)
+ // Mock timing returns 1000ms (below threshold)
+ MongoDocumentNodeStoreBuilder builder = new
MongoDocumentNodeStoreBuilder()
+ .setMongoQueryWarningThresholdMillis(20000);
+ store = new TestStore(mongoConnection.getMongoClient(),
+ mongoConnection.getDatabase(), builder, 1000);
+
+ logCustomizer.starting();
+
+ // Perform query with mocked 1000ms duration (below 20000ms threshold)
+ store.find(Collection.NODES, "testnode");
+
+ // No warning should be logged for queries completing below threshold
+ assertEquals("No warning should be logged for queries completing below
threshold",
+ 0, logCustomizer.getLogs().size());
+ }
+
+ @Test
+ public void queryWarningLoggedWhenExceedsThreshold() {
+ // Create store with 5000ms threshold, mock timing returns 10000ms
(exceeds threshold)
+ MongoDocumentNodeStoreBuilder builder = new
MongoDocumentNodeStoreBuilder()
+ .setMongoQueryWarningThresholdMillis(5000);
+ store = new TestStore(mongoConnection.getMongoClient(),
+ mongoConnection.getDatabase(), builder, 10000);
+
+ logCustomizer.starting();
+
+ // Perform query with mocked 10000ms duration (exceeds 5000ms
threshold)
+ store.find(Collection.NODES, "testnode");
+
+ // Warning should be logged
+ assertTrue("Warning should be logged when query exceeds threshold",
+ logCustomizer.getLogs().size() > 0);
+
+ // Verify warning message contains expected information
+ String logMessage = logCustomizer.getLogs().get(0);
+ assertTrue("Log message should contain query description",
+ logMessage.contains("findUncached"));
+ assertTrue("Log message should contain duration",
+ logMessage.contains("took"));
+ assertTrue("Log message should contain 'ms'",
+ logMessage.contains("ms"));
+ assertTrue("Log message should contain collection name",
+ logMessage.contains("nodes"));
+ }
+
+ @Test
+ public void warningIncludesQueryDetails() {
+ // Test that query details are included in warning message
+ MongoDocumentNodeStoreBuilder builder = new
MongoDocumentNodeStoreBuilder()
+ .setMongoQueryWarningThresholdMillis(5000);
+ store = new TestStore(mongoConnection.getMongoClient(),
+ mongoConnection.getDatabase(), builder, 10000);
+
+ logCustomizer.starting();
+
+ // Test with a specific key
+ store.find(Collection.NODES, "testnode");
+
+ // Verify warning was logged with details
+ assertTrue("At least one warning should be logged",
+ logCustomizer.getLogs().size() > 0);
+
+ String logMessage = logCustomizer.getLogs().get(0);
+ assertTrue("Log message should contain query details",
+ logMessage.contains("testnode") ||
logMessage.contains("findUncached"));
+ }
+
+ /**
+ * Test subclass that overrides startWatch() to return a Stopwatch with a
custom ticker.
+ * This allows testing the threshold logic without relying on actual query
performance.
+ */
+ private static class TestStore extends MongoDocumentStore {
+ private final long mockElapsedMillis;
+
+ public TestStore(MongoClient client, MongoDatabase db,
+ MongoDocumentNodeStoreBuilder builder,
+ long mockElapsedMillis) {
+ super(client, db, builder);
+ this.mockElapsedMillis = mockElapsedMillis;
+ }
+
+ @Override
+ protected Stopwatch startWatch() {
+ // Create a Stopwatch with a custom ticker that simulates the
specified elapsed time
+ // The ticker simulates time progression: first call returns 0,
subsequent calls add the mock duration
+ long startNanos = System.nanoTime();
+ long elapsedNanos =
TimeUnit.MILLISECONDS.toNanos(mockElapsedMillis);
+ long[] callCount = {0};
+
+ return Stopwatch.createStarted(() -> {
+ long count = callCount[0]++;
+ // Call 0 & 1: Constructor and start() - return start time
+ // Call 2+: elapsed() calls - return start time + elapsed
duration
+ return count < 2 ? startNanos : startNanos + elapsedNanos;
+ });
+ }
+ }
+}
