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..ac7ca71b3a5 --- /dev/null +++ b/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 + */ + +public class QueryResultDebugIterator implements Iterator { + + private static final Logger LOG = LoggerFactory.getLogger(QueryResultDebugIterator.class); + + private final Iterator 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 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); + } + } + + +} 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 } }; } 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 + } +}