Troubleshooting Slow Queries in AEM

Statement: Slow Query Classifications
Solution:

Slow Query Classifications
There are 3 main classifications of slow queries in AEM, listed by severity:
Index-less queries
Queries that do not resolve to an index and traverse the JCR's contents to collect results
Poorly restricted (or scoped) queries
Queries that resolve to an index, but must traverse all index entries to collect results
The large result set queries
Queries that return very large numbers of results.

Note:

• The first 2 classifications of queries (index-less and poorly restricted) are slow because they force the Oak query engine to inspect each potential result (content node or index entry) to identify which belong in the actual result set.
• In AEM 6.3, by default, when traversal of 100,000 is reached, the query fails and throws an exception.
• This limit does not exist by default in AEM versions prior to AEM 6.3, but can be set via the Apache Jackrabbit Query Engine Settings OSGi configuration and QueryEngineSettings JMX bean (property LimitReads).

1. Detecting Index-less Queries
During Development
Explain all queries and ensure their query plans do not contain the /* traverse explanation in them. Example traversing query plan:
PLAN: [nt:unstructured] as [a] /* traverse "/content//*" where ([a].[unindexedProperty] = 'some value') and (isdescendantnode([a], [/content])) */

Post-Deployment
Monitor the error.log for index-less traversal queries:
*INFO* org.apache.jackrabbit.oak.query.QueryImpl Traversal query (query without index) ...; consider creating an index
This message is only logged if no index is available, and if the query potentially traverses many nodes. Messages are not logged if an index is available, but the amount to traversing is small, and thus fast.
Visit the AEM Query Performance operations console and Explain slow queries looking for traversal or no index query explanations.

Query Performance
The Query Performance page allows the analysis of the slowest queries performed by the system. This information is provided by the repository in a JMX Mbean.
In Jackrabbit, the com.adobe.granite.QueryStat JMX Mbean provides this information, while in the Oak repository, it is offered by org.apache.jackrabbit.oak.QueryStats.
The page displays:
The time when the query was made
The language of the query
The number of times the query was issued
The statement of the query
The duration in milliseconds



Explain Query
For any given query, Oak attempts to figure out the best way to execute based on the Oak indexes defined in the repository under the oak:index node.
Depending on the query, different indexes may be chosen by Oak. Understanding how Oak is executing a query is the first step to optimizing the query.

The Explain Query is a tool that explains how Oak is executing a query. It can be accessed by going to Tools - Operations - Diagnosis from the AEM Welcome Screen, then clicking on Query Performance and switching over to the Explain Query tab.

Features

• Supports the Xpath, JCR-SQL and JCR-SQL2 query languages
• Reports the actual execution time of the provided query
• Detects slow queries and warns about queries that could be potentially slow
• Reports the Oak index used to execute the query
• Displays the actual Oak Query engine explanation
• Provides a click-to-load list of Slow and Popular queries

Once you are in the Explain Query UI, all you need to do in order to use it is enter the query and press the Explain button:



The first entry in the Query Explanation section is the actual explanation. The explanation will show the type of index that was used to execute the query.

The second entry is the execution plan.

Ticking the Include execution time box before running the query will also show the amount of time the query was executed, allowing for more information that can be used for optimizing the indexes for your application or deployment.



Detecting Poorly Restricted Queries
During Development
Explain all queries and ensure they resolve to an index tuned to match the query's property restrictions.

• Ideal query plan coverage has indexRules for all property restrictions, and at a minimum for the tightest property restrictions in the query.
• Queries that sort results, should resolve to a Lucene Property Index with index rules for the sorted by properties that set orderable=true.

For example, the default cqPageLucene does not have an index rule for jcr:content/cq:tags
Before adding the cq:tags index rule
cq:tags Index Rule
Does not exist out of the box
Query Builder query
type=cq:Page
property=jcr:content/cq:tags
property.value=my:tag

Query plan
[cq:Page] as [a] /* lucene:cqPageLucene(/oak:index/cqPageLucene) *:* where [a].[jcr:content/cq:tags] = 'my:tag' */
This query resolves to the cqPageLucene index, but because no property index rule exists for jcr:content or cq:tags, when this restriction is evaluated, every record in the cqPageLucene index is checked to determine a match. This means that if the index contains 1 million cq:Page nodes, then 1 million records are checked to determine the result set.

After adding the cq:tags index rule
cq:tags Index Rule
/oak:index/cqPageLucene/indexRules/cq:Page/properties/cqTags
@name=jcr:content/cq:tags
@propertyIndex=true

Query Builder query
type=cq:Page
property=jcr:content/cq:tags
property.value=myTagNamespace:myTag

Query plan
[cq:Page] as [a] /* lucene:cqPageLucene(/oak:index/cqPageLucene) jcr:content/cq:tags:my:tag where [a].[jcr:content/cq:tags] = 'my:tag' */
The addition of the indexRule for jcr:content/cq:tags in the cqPageLucene index allows cq:tags data to be stored in an optimized way.
When a query with the jcr:content/cq:tags restriction is performed, the index can look up results by value. That means that if 100 cq:Page nodes have myTagNamespace:myTag as a value, only those 100 results are returned, and the other 999,000 are excluded from the restriction checks, improving performance by a factor of 10,000.

Post-Deployment
Monitor the error.log for traversal queries:
*WARN* org.apache.jackrabbit.oak.spi.query.Cursors$TraversingCursor Traversed ### nodes ... consider creating an index or changing the query
Visit the AEM Query Performance operations console and Explain slow queries looking for query plans that do not resolve query property restrictions to index property rules.

Detecting Large Result Set Queries
During Development
Set low thresholds for oak.queryLimitInMemory (eg. 10000) and oak.queryLimitReads (eg. 5000) and optimize the expensive query when hitting an UnsupportedOperationException saying “The query read more than x nodes..."

Post-Deployment
Monitor the logs for queries triggering large node traversal or large heap memory consumption:
*WARN* ... java.lang.UnsupportedOperationException: The query read or traversed more than 100000 nodes. To avoid affecting other tasks, processing was stopped.
Optimize the query to reduce the number of traversed nodes

Monitor the logs for queries triggering large heap memory consumption:
*WARN* ... java.lang.UnsupportedOperationException: The query read more than 500000 nodes in memory. To avoid running out of memory, processing was stopped
Optimize the query to reduce the heap memory consumption
For AEM 6.0 - 6.2 versions, you can tune the threshold for node traversal via JVM parameters in the AEM start script to prevent large queries from 

overloading the environment. The recommended values are:
-Doak.queryLimitInMemory=500000
-Doak.queryLimitReads=100000
In AEM 6.3, the above 2 parameters are preconfigured by default and can be modified via the OSGi QueryEngineSettings.

More information available under http://jackrabbit.apache.org/oak/docs/query/query-engine.html#Slow_Queries_and_Read_Limits

Query Development Tools
Adobe Supported
Query Builder Debugger
A WebUI for executing Query Builder queries and generate the supporting XPath (for use in Explain Query or Oak Index Definition Generator).
Located on AEM at /libs/cq/search/content/querydebug.html
CRXDE Lite - Query Tool
A WebUI for executing XPath and JCR-SQL2 queries.
Located on AEM at /crx/de/index.jsp > Tools > Query...

Explain Query
An AEM Operations dashboard that provides a detailed explanation (Query plan, query time, and # of results) for any given XPATH or JCR-SQL2 query.

Slow/Popular Queries
An AEM Operations dashboard listing the recent slow and popular queries executed on AEM.

Index Manager
An AEM Operations WebUI displaying the indexes on the AEM instance; facilitates understanding what indexes already exist, can be targeted or augmented.

Logging

Query Builder logging
DEBUG @ com.day.cq.search.impl.builder.QueryImpl
Oak query execution logging
DEBUG @ org.apache.jackrabbit.oak.query

Apache Jackrabbit Query Engine Settings OSGi Config
OSGi configuration that configures failure behavior for traversing queries.
Located on AEM at /system/console/configMgr#org.apache.jackrabbit.oak.query.QueryEngineSettingsService

NodeCounter JMX MBean
JMX MBean used to estimate the number of nodes in content trees in AEM.
Located on AEM at /system/console/jmx/org.apache.jackrabbit.oak%3Aname%3DnodeCounter%2Ctype%3DNodeCounter

Community Supported
Oak Index Definition Generator
Generate optimal Lucence Property Index from XPath or JCR-SQL2 query statements.

AEM Chrome Plug-in
Google Chrome web browser extension that exposes per-request log data, including executed queries and their query plans, in the browser's dev tools console.

Requires Sling Log Tracer 1.0.2+ to be installed and enabled on AEM.