From 6d33cf4b75b76696016668b8a099dd5805b93a29 Mon Sep 17 00:00:00 2001 From: Joerg Hoh Date: Mon, 14 Jul 2025 10:01:38 +0200 Subject: [PATCH 1/4] OAK-11672 log warnings when fetching large result sets --- .../oak/jcr/query/QueryManagerImpl.java | 2 +- .../jcr/query/QueryResultDebugIterator.java | 83 +++++++++++++++++++ .../oak/jcr/query/QueryResultImpl.java | 15 +++- 3 files changed, 96 insertions(+), 4 deletions(-) create mode 100644 oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultDebugIterator.java diff --git a/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryManagerImpl.java b/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryManagerImpl.java index b169e3ebdb3..afd87443670 100644 --- a/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryManagerImpl.java +++ b/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryManagerImpl.java @@ -142,7 +142,7 @@ public QueryResult executeQuery(String statement, String language, queryOpsLogger.debug("Executed query [{}] in [{}] ms", statement, millis); sessionContext.getStatisticManager() .logQueryEvaluationTime(language, statement, millis); - return new QueryResultImpl(sessionContext, r); + return new QueryResultImpl(sessionContext, r, statement, language); } catch (IllegalArgumentException e) { throw new InvalidQueryException(e); } catch (ParseException e) { diff --git a/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultDebugIterator.java b/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultDebugIterator.java new file mode 100644 index 00000000000..ac0505cdd4b --- /dev/null +++ b/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultDebugIterator.java @@ -0,0 +1,83 @@ +/* + * 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.jcr.query; + +import java.util.Iterator; + +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +/** + * An iterator which prints warnings when a certain number of elements were read from it. + * @param + */ + +public class QueryResultDebugIterator implements Iterator { + + private static final Logger LOG = LoggerFactory.getLogger(QueryResultDebugIterator.class); + + private Iterator iter; + private int count; + private String query; + private String queryLanguage; + + private static final int FIRST_LOG_THRESHOLD = 1_000; + private static final int SECOND_LOG_THRESHOLD = 10_000; + + + public QueryResultDebugIterator (Iterator it, String query, String queryLanguage) { + this.iter = it; + this.query = query; + this.queryLanguage = queryLanguage; + } + + @Override + public boolean hasNext() { + return iter.hasNext(); + } + + @Override + public K next() { + mark(); + if (count >= FIRST_LOG_THRESHOLD) { + potentiallyLog(); + } + return iter.next(); + } + + protected void mark() { + count++; + } + + private void potentiallyLog() { + if (count == FIRST_LOG_THRESHOLD) { + LOG.warn("Read {} results from result set of query='{}', query language='{}')", count, query, queryLanguage); + return; + } + if (count == SECOND_LOG_THRESHOLD) { + LOG.warn("Read {} results from result set of query='{}', query language='{}')", count, query, queryLanguage); + return; + } + if (count > SECOND_LOG_THRESHOLD && count % 1000 == 0) { + LOG.trace("Read {} results from result set of query='{}', query language='{}')", count, query, queryLanguage); + } + } + + +} diff --git a/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultImpl.java b/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultImpl.java index 3d5de8380e0..0ece0831c29 100644 --- a/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultImpl.java +++ b/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultImpl.java @@ -61,11 +61,16 @@ public class QueryResultImpl implements QueryResult { private final PartialValueFactory valueFactory; - public QueryResultImpl(SessionContext sessionContext, Result result) { + private final String queryStatement; + private final String queryLanguage; + + public QueryResultImpl(SessionContext sessionContext, Result result, String query, String queryLanguage) { this.sessionContext = sessionContext; this.sessionDelegate = sessionContext.getSessionDelegate(); this.result = result; this.valueFactory = new PartialValueFactory(sessionContext, sessionContext.getBlobAccessProvider()); + this.queryStatement = query; + this.queryLanguage = queryLanguage; } @Override @@ -231,10 +236,14 @@ public void remove() { fastSizeCallback = result; } }); - return new NodeIteratorAdapter(prefIt) { + final QueryResultDebugIterator> debugIt = + new QueryResultDebugIterator<>(prefIt, queryStatement, queryLanguage); + + return new NodeIteratorAdapter(debugIt) { @Override public long getSize() { - return prefIt.size(); + return prefIt.size(); // bypass the debugIterator, as it does not influence + // the result set } }; } From 0c67dcea1c9761f17e6a0e372b12743d567c7f9f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?J=C3=B6rg=20Hoh?= Date: Mon, 22 Dec 2025 16:20:18 +0100 Subject: [PATCH 2/4] Update oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultDebugIterator.java PR feedback Co-authored-by: Thomas Mueller --- .../jackrabbit/oak/jcr/query/QueryResultDebugIterator.java | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultDebugIterator.java b/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultDebugIterator.java index ac0505cdd4b..06474d0bdab 100644 --- a/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultDebugIterator.java +++ b/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultDebugIterator.java @@ -32,10 +32,10 @@ public class QueryResultDebugIterator implements Iterator { private static final Logger LOG = LoggerFactory.getLogger(QueryResultDebugIterator.class); - private Iterator iter; + private final Iterator iter; + private final String query; + private final String queryLanguage; private int count; - private String query; - private String queryLanguage; private static final int FIRST_LOG_THRESHOLD = 1_000; private static final int SECOND_LOG_THRESHOLD = 10_000; From 6ae1220d1aae64a3b5ef85cb288fde1abfc2ea3e Mon Sep 17 00:00:00 2001 From: Joerg Hoh Date: Mon, 22 Dec 2025 17:47:44 +0100 Subject: [PATCH 3/4] OAK-11672 PR feedback + improvements --- .../jcr/query/QueryResultDebugIterator.java | 27 ++++++++----------- 1 file changed, 11 insertions(+), 16 deletions(-) diff --git a/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultDebugIterator.java b/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultDebugIterator.java index 06474d0bdab..ac7ca71b3a5 100644 --- a/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultDebugIterator.java +++ b/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultDebugIterator.java @@ -35,7 +35,7 @@ public class QueryResultDebugIterator implements Iterator { private final Iterator iter; private final String query; private final String queryLanguage; - private int count; + private int resultsRead; private static final int FIRST_LOG_THRESHOLD = 1_000; private static final int SECOND_LOG_THRESHOLD = 10_000; @@ -54,28 +54,23 @@ public boolean hasNext() { @Override public K next() { - mark(); - if (count >= FIRST_LOG_THRESHOLD) { + resultsRead++; + if (resultsRead >= FIRST_LOG_THRESHOLD) { potentiallyLog(); } return iter.next(); } - protected void mark() { - count++; - } - private void potentiallyLog() { - if (count == FIRST_LOG_THRESHOLD) { - LOG.warn("Read {} results from result set of query='{}', query language='{}')", count, query, queryLanguage); - return; - } - if (count == SECOND_LOG_THRESHOLD) { - LOG.warn("Read {} results from result set of query='{}', query language='{}')", count, query, queryLanguage); - return; + + boolean shouldWarn = ((resultsRead == FIRST_LOG_THRESHOLD) + || (resultsRead == SECOND_LOG_THRESHOLD)); + + if (shouldWarn) { + LOG.warn("Read {} results from result set of query='{}', query language='{}')", resultsRead, query, queryLanguage); } - if (count > SECOND_LOG_THRESHOLD && count % 1000 == 0) { - LOG.trace("Read {} results from result set of query='{}', query language='{}')", count, query, queryLanguage); + if (resultsRead > SECOND_LOG_THRESHOLD && resultsRead % 1000 == 0) { + LOG.trace("Read {} results from result set of query='{}', query language='{}')", resultsRead, query, queryLanguage); } } From bb4782369ba517f721968ee8a603e34d52101c88 Mon Sep 17 00:00:00 2001 From: Joerg Hoh Date: Tue, 23 Dec 2025 12:35:08 +0100 Subject: [PATCH 4/4] OAK-11672 add simple unittest --- .../query/QueryResultDebugIteratorTest.java | 54 +++++++++++++++++++ 1 file changed, 54 insertions(+) create mode 100644 oak-jcr/src/test/java/org/apache/jackrabbit/oak/jcr/query/QueryResultDebugIteratorTest.java diff --git a/oak-jcr/src/test/java/org/apache/jackrabbit/oak/jcr/query/QueryResultDebugIteratorTest.java b/oak-jcr/src/test/java/org/apache/jackrabbit/oak/jcr/query/QueryResultDebugIteratorTest.java new file mode 100644 index 00000000000..81408c88223 --- /dev/null +++ b/oak-jcr/src/test/java/org/apache/jackrabbit/oak/jcr/query/QueryResultDebugIteratorTest.java @@ -0,0 +1,54 @@ +package org.apache.jackrabbit.oak.jcr.query; + +import static org.junit.Assert.assertEquals; + +import java.util.Arrays; +import java.util.Iterator; +import java.util.List; + +import org.apache.jackrabbit.oak.commons.junit.LogCustomizer; +import org.junit.After; +import org.junit.Before; +import org.junit.Test; + +import ch.qos.logback.classic.Level; + +public class QueryResultDebugIteratorTest { + + private static final String QUERY_STRING = "JCR QUERY"; + private static final String QUERY_LANGUAGE="xpath"; + + private static final int QUERY_RESULT_SIZE = 11_000; + + LogCustomizer logCustomizer; + + @Before + public void setup() { + logCustomizer = LogCustomizer.forLogger(QueryResultDebugIterator.class) + .enable(Level.TRACE) + .create(); + } + + @After + public void cleanup() { + logCustomizer.finished(); + } + + @Test + public void testLogging() { + Integer[] rawQueryResult = new Integer[QUERY_RESULT_SIZE]; + for (int i=0; i < QUERY_RESULT_SIZE; i++) { + rawQueryResult[i] = i; + } + Iterator rawQueryIterator = Arrays.asList(rawQueryResult).iterator(); + QueryResultDebugIterator qrdi = new QueryResultDebugIterator(rawQueryIterator,QUERY_LANGUAGE,QUERY_STRING); + + logCustomizer.starting(); + // read all results + for (int i=0; i < QUERY_RESULT_SIZE; i++) { + assertEquals(i, qrdi.next()); + } + List logs = logCustomizer.getLogs(); + assertEquals(3, logs.size()); // for 1_000, 10_000 and 11_000 + } +}