/*
* #%L
* ACS AEM Tools Bundle
* %%
* Copyright (C) 2014 Adobe
* %%
* Licensed 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.
* #L%
*/
package com.adobe.acs.tools.explain_query.impl;
import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.PatternLayout;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.classic.spi.LoggingEvent;
import ch.qos.logback.classic.turbo.TurboFilter;
import ch.qos.logback.core.Layout;
import ch.qos.logback.core.spi.FilterReply;
import com.adobe.acs.commons.util.OsgiPropertyUtil;
import com.day.cq.search.PredicateGroup;
import com.day.cq.search.QueryBuilder;
import com.day.cq.search.result.SearchResult;
import org.apache.commons.lang.ArrayUtils;
import org.apache.commons.lang.StringUtils;
import org.apache.felix.scr.annotations.Activate;
import org.apache.felix.scr.annotations.Deactivate;
import org.apache.felix.scr.annotations.Property;
import org.apache.felix.scr.annotations.PropertyUnbounded;
import org.apache.felix.scr.annotations.Reference;
import org.apache.felix.scr.annotations.sling.SlingServlet;
import org.apache.jackrabbit.api.jmx.QueryStatManagerMBean;
import org.apache.sling.api.SlingHttpServletRequest;
import org.apache.sling.api.SlingHttpServletResponse;
import org.apache.sling.api.resource.ResourceResolver;
import org.apache.sling.api.servlets.SlingAllMethodsServlet;
import org.apache.sling.commons.json.JSONArray;
import org.apache.sling.commons.json.JSONException;
import org.apache.sling.commons.json.JSONObject;
import org.apache.sling.commons.osgi.PropertiesUtil;
import org.osgi.framework.Bundle;
import org.osgi.framework.BundleContext;
import org.osgi.framework.ServiceRegistration;
import org.osgi.framework.Version;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.slf4j.Marker;
import javax.jcr.NodeIterator;
import javax.jcr.RepositoryException;
import javax.jcr.Session;
import javax.jcr.query.Query;
import javax.jcr.query.QueryManager;
import javax.jcr.query.QueryResult;
import javax.jcr.query.Row;
import javax.jcr.query.RowIterator;
import javax.management.openmbean.CompositeData;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;
import java.util.ArrayList;
import java.util.Collection;
import java.util.Collections;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
import java.util.UUID;
import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.atomic.AtomicInteger;
import java.util.concurrent.atomic.AtomicReference;
import java.util.regex.Matcher;
import java.util.regex.Pattern;
@SlingServlet(
label = "ACS AEM Tools - Explain Query Servlet",
description = "End-point for Apache Jackrabbit Oak query explanations.",
methods = { "GET", "POST" },
resourceTypes = { "acs-tools/components/explain-query" },
selectors = { "explain" },
extensions = { "json" },
metatype = true
)
public class ExplainQueryServlet extends SlingAllMethodsServlet {
private static final Logger log = LoggerFactory.getLogger(ExplainQueryServlet.class);
//MDC key defined in org.apache.jackrabbit.oak.query.QueryEngineImpl
private static final String OAK_QUERY_ANALYZE = "oak.query.analyze";
private static final String SQL = "sql";
private static final String SQL2 = "JCR-SQL2";
private static final String XPATH = "xpath";
private static final String QUERY_BUILDER = "queryBuilder";
private static final String[] LANGUAGES = new String[]{SQL, SQL2, XPATH};
private static final Pattern PROPERTY_INDEX_PATTERN =
Pattern.compile("\\/\\*\\sproperty\\s([^\\s=]+)[=\\s]");
private static final Pattern FILTER_PATTERN =
Pattern.compile("\\[[^\\s]+\\]\\sas\\s\\[[^\\s]+\\]\\s\\/\\*\\sFilter\\(");
@Property(label = "Query Logger Names",
description = "Logger names from which logs need to be collected while a query is executed. "
+ "Provide in the format '<package-name>=<mdc-filter-name>' where <mdc-filter-name>' is optional.",
unbounded = PropertyUnbounded.ARRAY,
value = {
"org.apache.jackrabbit.oak.query=" + OAK_QUERY_ANALYZE,
"org.apache.jackrabbit.oak.plugins.index=" + OAK_QUERY_ANALYZE,
"com.day.cq.search.impl.builder.QueryImpl"
}
)
private static final String PROP_LOGGER_NAMES = "log.logger-names";
private static final String DEFAULT_PATTERN = "%msg%n";
@Property(label = "Log Pattern",
description = "Message Pattern for formatting the log messages. [ Default: " + DEFAULT_PATTERN + " ]",
value = DEFAULT_PATTERN
)
private static final String PROP_MSG_PATTERN = "log.pattern";
private static final int DEFAULT_LIMIT = 100;
@Property(label = "Log Limit",
description = "Number of log message which should be collected in memory",
intValue = DEFAULT_LIMIT
)
private static final String PROP_LOG_COUNT_LIMIT = "log.message-count-limit";
@Reference
private QueryStatManagerMBean queryStatManagerMBean;
@Reference
private QueryBuilder queryBuilder;
private QueryLogCollector logCollector = null;
private final AtomicReference<ServiceRegistration> logCollectorReg = new AtomicReference<ServiceRegistration>();
private final AtomicInteger logCollectorRegCount = new AtomicInteger();
private BundleContext bundleContext;
private Map<String, String> loggers = new HashMap<String, String>();
private String pattern = DEFAULT_PATTERN;
private int msgCountLimit = DEFAULT_LIMIT;
@SuppressWarnings("unchecked")
@Override
protected final void doGet(SlingHttpServletRequest request, SlingHttpServletResponse response)
throws ServletException, IOException {
final JSONObject json = new JSONObject();
try {
json.put("slowQueries",
this.compositeQueryDataToJSON((Collection<CompositeData>) queryStatManagerMBean
.getSlowQueries().values())
);
} catch (JSONException e) {
log.error("Unable to serial Slow Queries into JSON: {}", e.getMessage());
}
try {
json.put("popularQueries", this.compositeQueryDataToJSON((Collection<CompositeData>) queryStatManagerMBean
.getPopularQueries().values()));
} catch (JSONException e) {
log.error("Unable to serial Popular Queries into JSON: {}", e.getMessage());
}
response.setContentType("application/json");
response.getWriter().print(json.toString());
}
@Override
protected final void doPost(SlingHttpServletRequest request, SlingHttpServletResponse response)
throws ServletException, IOException {
boolean logCollectorRegistered = false;
final ResourceResolver resourceResolver = request.getResourceResolver();
String statement = StringUtils.removeStartIgnoreCase(request.getParameter("statement"), "EXPLAIN ");
String language = request.getParameter("language");
final Session session = resourceResolver.adaptTo(Session.class);
try {
// Mark this thread as an Explain Query thread for TurboFiltering
registerLogCollector();
logCollectorRegistered = true;
final JSONObject json = new JSONObject();
json.put("statement", statement);
json.put("language", language);
json.put("explain", explainQuery(session, statement, language));
boolean collectExecutionTime = "true".equals(
StringUtils.defaultIfEmpty(request.getParameter("executionTime"), "false"));
boolean collectCount = "true".equals(
StringUtils.defaultIfEmpty(request.getParameter("resultCount"), "false"));
if (collectExecutionTime) {
json.put("heuristics", this.getHeuristics(session, statement, language, collectCount));
}
response.setContentType("application/json");
response.getWriter().print(json.toString());
} catch (RepositoryException e) {
log.error(e.getMessage());
response.sendError(HttpServletResponse.SC_INTERNAL_SERVER_ERROR);
} catch (JSONException e) {
log.error(e.getMessage());
response.sendError(HttpServletResponse.SC_INTERNAL_SERVER_ERROR);
} finally {
if (logCollectorRegistered) {
unregisterLogCollector();
}
}
}
private JSONObject explainQuery(final Session session, final String statement, final String language)
throws RepositoryException, JSONException {
final QueryManager queryManager = session.getWorkspace().getQueryManager();
final JSONObject json = new JSONObject();
final String collectorKey = startCollection();
final QueryResult queryResult;
final String effectiveLanguage;
final String effectiveStatement;
if (language.equals(QUERY_BUILDER)) {
effectiveLanguage = XPATH;
final String[] lines = StringUtils.split(statement, '\n');
final Map<String, String> params = OsgiPropertyUtil.toMap(lines, "=", false, null, true);
final com.day.cq.search.Query query = queryBuilder.createQuery(PredicateGroup.create(params), session);
effectiveStatement = query.getResult().getQueryStatement();
} else {
effectiveStatement = statement;
effectiveLanguage = language;
}
try {
final Query query = queryManager.createQuery("explain " + effectiveStatement, effectiveLanguage);
queryResult = query.execute();
} finally {
synchronized (this.logCollector) {
if (this.logCollector != null) {
List<String> logs = this.logCollector.getLogs(collectorKey);
json.put("logs", this.logCollector.getLogs(collectorKey));
if (logs.size() == this.logCollector.msgCountLimit) {
json.put("logsTruncated", true);
}
}
stopCollection(collectorKey);
}
}
final RowIterator rows = queryResult.getRows();
final Row firstRow = rows.nextRow();
final String plan = firstRow.getValue("plan").getString();
json.put("plan", plan);
final JSONArray propertyIndexes = new JSONArray();
final Matcher propertyMatcher = PROPERTY_INDEX_PATTERN.matcher(plan);
/* Property Index */
while (propertyMatcher.find()) {
final String match = propertyMatcher.group(1);
if (StringUtils.isNotBlank(match)) {
propertyIndexes.put(StringUtils.stripToEmpty(match));
}
}
if (propertyIndexes.length() > 0) {
json.put("propertyIndexes", propertyIndexes);
}
final Matcher filterMatcher = FILTER_PATTERN.matcher(plan);
if (filterMatcher.find()) {
/* Filter (nodeType index) */
propertyIndexes.put("nodeType");
json.put("propertyIndexes", propertyIndexes);
json.put("slow", true);
}
if (StringUtils.contains(plan, " /* traverse ")) {
/* Traversal */
json.put("traversal", true);
json.put("slow", true);
}
if (StringUtils.contains(plan, " /* aggregate ")) {
/* Aggregate - Fulltext */
json.put("aggregate", true);
}
return json;
}
private JSONObject getHeuristics(final Session session,
final String statement,
final String language,
final boolean getCount) throws RepositoryException, JSONException {
int count = 0;
final QueryManager queryManager = session.getWorkspace().getQueryManager();
final JSONObject json = new JSONObject();
long executionTime;
long getNodesTime;
long countTime = 0L;
if (language.equals(QUERY_BUILDER)) {
final String[] lines = StringUtils.split(statement, '\n');
final Map<String, String> params = OsgiPropertyUtil.toMap(lines, "=", false, null, true);
final com.day.cq.search.Query query = queryBuilder.createQuery(PredicateGroup.create(params), session);
long start = System.currentTimeMillis();
SearchResult result = query.getResult();
executionTime = System.currentTimeMillis() - start;
start = System.currentTimeMillis();
result.getNodes();
getNodesTime = System.currentTimeMillis() - start;
if (getCount) {
count = result.getHits().size();
countTime = System.currentTimeMillis() - start;
}
} else {
final Query query = queryManager.createQuery(statement, language);
long start = System.currentTimeMillis();
final QueryResult queryResult = query.execute();
executionTime = System.currentTimeMillis() - start;
start = System.currentTimeMillis();
queryResult.getNodes();
getNodesTime = System.currentTimeMillis() - start;
if (getCount) {
final NodeIterator nodes = queryResult.getNodes();
while (nodes.hasNext()) {
nodes.next();
count++;
}
countTime = System.currentTimeMillis() - start;
}
}
json.put("executeTime", executionTime);
json.put("getNodesTime", getNodesTime);
if (getCount) {
json.put("count", count);
json.put("countTime", countTime);
}
json.put("totalTime", executionTime + getNodesTime + countTime);
return json;
}
private JSONArray compositeQueryDataToJSON(Collection<CompositeData> queries) throws JSONException {
final JSONArray jsonArray = new JSONArray();
for (CompositeData query : queries) {
Long duration = (Long) query.get("duration");
Integer occurrenceCount = (Integer) query.get("occurrenceCount");
String language = (String) query.get("language");
String statement = (String) query.get("statement");
if (!ArrayUtils.contains(LANGUAGES, language)) {
// Not a supported language
continue;
} else if (StringUtils.startsWithIgnoreCase(statement, "EXPLAIN ")
|| StringUtils.startsWithIgnoreCase(statement, "MEASURE ")) {
// Don't show EXPLAIN or MEASURE queries
continue;
}
final JSONObject json = new JSONObject();
try {
json.put("duration", duration);
json.put("language", language);
json.put("occurrenceCount", occurrenceCount);
json.put("statement", statement);
jsonArray.put(json);
} catch (JSONException e) {
log.warn("Could not add query to results [ {} ]", statement);
continue;
}
}
return jsonArray;
}
private String startCollection() {
final String collectorKey = UUID.randomUUID().toString();
MDC.put(QueryLogCollector.COLLECTOR_KEY, collectorKey);
return collectorKey;
}
private void stopCollection(String key) {
synchronized (this.logCollector) {
MDC.remove(key);
if (this.logCollector != null) {
this.logCollector.stopCollection(key);
}
}
}
private static boolean checkMDCSupport(BundleContext context) {
//MDC support is present since 1.0.9 s
Version versionWithMDCSupport = new Version(1, 0, 9);
for (Bundle b : context.getBundles()) {
if ("org.apache.jackrabbit.oak-core".equals(b.getSymbolicName())) {
return versionWithMDCSupport.compareTo(b.getVersion()) <= 0;
}
}
//By default it is assumed that MDC support is present
return true;
}
/**
* TurboFilters causes slowness as they are executed on critical path
* Hence care is taken to only register the filter only when required
* Logic below ensures that filter is only registered for the duration
* or request which needs to be "monitored".
*
* If multiple such request are performed then also only one filter gets
* registered
*/
private void registerLogCollector() {
synchronized (logCollectorRegCount) {
int count = logCollectorRegCount.getAndIncrement();
if (count == 0) {
ServiceRegistration reg = bundleContext.registerService(TurboFilter.class.getName(),
this.logCollector, null);
logCollectorReg.set(reg);
}
}
}
private void unregisterLogCollector() {
synchronized (logCollectorRegCount) {
int count = logCollectorRegCount.decrementAndGet();
if (count == 0) {
ServiceRegistration reg = logCollectorReg.getAndSet(null);
reg.unregister();
}
}
}
@Activate
private void activate(Map<String, ?> config, BundleContext context) {
this.bundleContext = context;
this.loggers = OsgiPropertyUtil.toMap(PropertiesUtil.toStringArray(
config.get(PROP_LOGGER_NAMES), new String[0]), "=", true, null);
if (loggers != null && !loggers.isEmpty()) {
this.pattern = PropertiesUtil.toString(config.get(PROP_MSG_PATTERN), DEFAULT_PATTERN);
this.msgCountLimit = PropertiesUtil.toInteger(config.get(PROP_LOG_COUNT_LIMIT), DEFAULT_LIMIT);
// Create a single logCollector; this will be used as TurboFilters are register with the execution of
// this Servlet
this.logCollector = new QueryLogCollector(loggers, pattern, msgCountLimit, checkMDCSupport(context));
} else {
this.logCollector = null;
}
}
@Deactivate
private void deactivate() {
ServiceRegistration reg = logCollectorReg.getAndSet(null);
if (reg != null) {
reg.unregister();
}
}
private static final class QueryLogCollector extends TurboFilter {
private static final String COLLECTOR_KEY = "collectorKey";
private final Map<String, String> loggers;
private final Layout<ILoggingEvent> layout;
private final int msgCountLimit;
private final Map<String, List<ILoggingEvent>> logEvents
= new ConcurrentHashMap<String, List<ILoggingEvent>>();
private final boolean mdcEnabled;
private QueryLogCollector(Map<String, String> loggers, String pattern, int msgCountLimit, boolean
mdcEnabled) {
this.loggers = loggers;
this.msgCountLimit = msgCountLimit;
this.layout = createLayout(pattern);
this.mdcEnabled = mdcEnabled;
if (!mdcEnabled) {
log.debug("Current Oak version does not provide MDC. Explain log would have some extra entries");
}
}
@Override
public FilterReply decide(Marker marker, ch.qos.logback.classic.Logger logger,
Level level, String format, Object[] params, Throwable t) {
/** NO LOGGING IN THIS METHOD **/
// If request is NOT an Explain Query generated thread, then always reply NEUTRAL
// This check is extremely fast and incur almost no overhead.
String collectorKey = MDC.get(COLLECTOR_KEY);
if (collectorKey == null) {
return FilterReply.NEUTRAL;
}
if (!acceptLogStatement(logger.getName())) {
return FilterReply.NEUTRAL;
}
//isXXXEnabled call. Accept the call to allow actual message to be logged
if (format == null) {
return FilterReply.ACCEPT;
}
ILoggingEvent logEvent = new LoggingEvent(ch.qos.logback.classic.Logger.FQCN,
logger, level, format, t, params);
log(collectorKey, logEvent);
// Return NEUTRAL to allow normal logging of message depending on level
return FilterReply.NEUTRAL;
}
public List<String> getLogs(String collectorKey) {
List<ILoggingEvent> eventList = logEvents.get(collectorKey);
if (eventList == null) {
return Collections.emptyList();
}
List<String> result = new ArrayList<String>(eventList.size());
for (ILoggingEvent e : eventList) {
result.add(layout.doLayout(e));
}
return result;
}
public void stopCollection(String key) {
logEvents.remove(key);
}
private void log(String collectorKey, ILoggingEvent e) {
List<ILoggingEvent> eventList = logEvents.get(collectorKey);
if (eventList == null) {
eventList = new ArrayList<ILoggingEvent>();
logEvents.put(collectorKey, eventList);
}
if (eventList.size() < msgCountLimit) {
eventList.add(e);
}
}
private boolean acceptLogStatement(String name) {
for (final Map.Entry<String, String> entry : this.loggers.entrySet()) {
if (name.startsWith(entry.getKey())) {
// log entry logger matches a configured logger
if (!mdcEnabled) {
// If MDC is not enabled, then matching logger name is good enough
return true;
} else if (mdcEnabled && entry.getValue() == null) {
// If MDC is enabled, but the logger is not configured to use MDC filtering then accept it
return true;
} else if (mdcEnabled && entry.getValue() != null && MDC.get(entry.getValue()) != null) {
// If MDC is enabled and a MDC filter value is specified, then the entry must have the
// MDC value
return true;
} else {
return false;
}
}
}
return false;
}
private static Layout<ILoggingEvent> createLayout(String pattern) {
PatternLayout pl = new PatternLayout();
pl.setPattern(pattern);
pl.setOutputPatternAsHeader(false);
pl.setContext((LoggerContext) LoggerFactory.getILoggerFactory());
pl.start();
return pl;
}
}
}