OAK-11672 log warnings when fetching large result sets

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) {

oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultDebugIterator.java

@@ -0,0 +1,78 @@
+/*
+ * 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 <K>
+ */
+
+public class QueryResultDebugIterator<K> implements Iterator<K> {
+
+    private static final Logger LOG = LoggerFactory.getLogger(QueryResultDebugIterator.class);
+
+    private final Iterator<K> iter;
+    private final String query;
+    private final String queryLanguage;
+    private int resultsRead;
+
+    private static final int FIRST_LOG_THRESHOLD = 1_000;
+    private static final int SECOND_LOG_THRESHOLD = 10_000;
+
+
+    public QueryResultDebugIterator (Iterator<K> 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() {
+        resultsRead++;
+        if (resultsRead >= FIRST_LOG_THRESHOLD) {
+            potentiallyLog();
+        }
+        return iter.next();
+    }
+
+    private void potentiallyLog() {
+
+        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 (resultsRead > SECOND_LOG_THRESHOLD && resultsRead % 1000 == 0) {
+            LOG.trace("Read {} results from result set of query='{}', query language='{}')", resultsRead, query, queryLanguage);
+        }
+    }
+
+
+}

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<NodeImpl<? extends NodeDelegate>> 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
             }
         };
     }

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<Integer> rawQueryIterator = Arrays.asList(rawQueryResult).iterator();
+        QueryResultDebugIterator<?> qrdi = new QueryResultDebugIterator<Integer>(rawQueryIterator,QUERY_LANGUAGE,QUERY_STRING);
+
+        logCustomizer.starting();
+        // read all results
+        for (int i=0; i < QUERY_RESULT_SIZE; i++) {
+            assertEquals(i, qrdi.next());
+        }
+        List<String> logs =  logCustomizer.getLogs();
+        assertEquals(3, logs.size()); // for 1_000, 10_000 and 11_000
+    }
+}