ExplainQueryServlet.java
20.7 KB
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
/*
* Decompiled with CFR 0_118.
*
* Could not load the following classes:
* ch.qos.logback.classic.Level
* ch.qos.logback.classic.Logger
* ch.qos.logback.classic.LoggerContext
* ch.qos.logback.classic.PatternLayout
* ch.qos.logback.classic.spi.ILoggingEvent
* ch.qos.logback.classic.spi.LoggingEvent
* ch.qos.logback.classic.turbo.TurboFilter
* ch.qos.logback.core.Context
* ch.qos.logback.core.Layout
* ch.qos.logback.core.spi.FilterReply
* javax.jcr.NodeIterator
* javax.jcr.RepositoryException
* javax.jcr.Session
* javax.jcr.Value
* javax.jcr.Workspace
* javax.jcr.query.Query
* javax.jcr.query.QueryManager
* javax.jcr.query.QueryResult
* javax.jcr.query.Row
* javax.jcr.query.RowIterator
* javax.servlet.ServletException
* org.apache.commons.lang.StringUtils
* org.apache.felix.scr.annotations.Activate
* org.apache.felix.scr.annotations.Deactivate
* org.apache.felix.scr.annotations.Modified
* org.apache.felix.scr.annotations.Property
* org.apache.felix.scr.annotations.PropertyUnbounded
* org.apache.felix.scr.annotations.sling.SlingServlet
* org.apache.sling.api.SlingHttpServletRequest
* org.apache.sling.api.SlingHttpServletResponse
* org.apache.sling.api.resource.ResourceResolver
* org.apache.sling.api.servlets.SlingAllMethodsServlet
* org.apache.sling.commons.json.JSONArray
* org.apache.sling.commons.json.JSONException
* org.apache.sling.commons.json.JSONObject
* org.apache.sling.commons.osgi.PropertiesUtil
* org.osgi.framework.Bundle
* org.osgi.framework.BundleContext
* org.osgi.framework.ServiceRegistration
* org.osgi.framework.Version
* org.slf4j.Logger
* org.slf4j.LoggerFactory
* org.slf4j.MDC
* org.slf4j.Marker
*/
package com.adobe.granite.queries.impl.explain.query;
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.Context;
import ch.qos.logback.core.Layout;
import ch.qos.logback.core.spi.FilterReply;
import java.io.IOException;
import java.io.PrintWriter;
import java.util.ArrayList;
import java.util.Collection;
import java.util.Collections;
import java.util.Dictionary;
import java.util.HashMap;
import java.util.LinkedHashMap;
import java.util.List;
import java.util.Map;
import java.util.Set;
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;
import javax.jcr.NodeIterator;
import javax.jcr.RepositoryException;
import javax.jcr.Session;
import javax.jcr.Value;
import javax.jcr.Workspace;
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.servlet.ServletException;
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.Modified;
import org.apache.felix.scr.annotations.Property;
import org.apache.felix.scr.annotations.PropertyUnbounded;
import org.apache.felix.scr.annotations.sling.SlingServlet;
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;
@SlingServlet(label="Adobe Granite - Explain Query Servlet", description="End-point for Apache Jackrabbit Oak query explanations.", methods={"POST"}, selectors={"explain"}, extensions={"json"}, metatype=1, resourceTypes={"granite/operations/components/diagnosis/tool/queryperformance"})
public class ExplainQueryServlet
extends SlingAllMethodsServlet {
private static final Logger log = LoggerFactory.getLogger(ExplainQueryServlet.class);
private static final String OAK_QUERY_ANALYZE = "oak.query.analyze";
private static final String LANGUAGE = "language";
private static final String STATEMENT = "statement";
private static final String EXPLAIN = "explain";
private static final String LOGS = "logs";
private static final String LOGS_TRUNCATED = "logsTruncated";
private static final String PLAN = "plan";
private static final String EXECUTION_TIME = "executionTime";
private static final String HEURISTICS = "heuristics";
private static final String PROPERTY_INDEXES = "propertyIndexes";
private static final String SLOW = "slow";
private static final String TRAVERSAL = "traversal";
private static final String AGGREGATE = "aggregate";
private static final String GET_NODES_TIME = "getNodesTime";
private static final String TOTAL_TIME = "totalTime";
private static final String NODE_COUNT = "count";
private static final String NODE_COUNT_TIME = "countTime";
private static final Pattern PROPERTY_INDEX_PATTERN = Pattern.compile("\\/\\*\\sproperty\\s([^\\s=]+)[=\\s]");
private static final Pattern LUCENE_INDEX_PATTERN = Pattern.compile("\\/\\*\\slucene:([^\\s\\*]+)[\\s\\*]");
@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", "org.apache.jackrabbit.oak.plugins.index"})
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: %msg%n ]", value={"%msg%n"})
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={100})
private static final String PROP_LOG_COUNT_LIMIT = "log.message-count-limit";
private final AtomicReference<ServiceRegistration> logCollectorReg = new AtomicReference();
private final AtomicReference<QueryLogCollector> logCollector = new AtomicReference();
private final AtomicInteger logCollectorRegCount = new AtomicInteger();
private static String logPattern;
private static Map<String, String> loggers;
private static int messageCountLimit;
private BundleContext bundleContext;
protected final void doPost(SlingHttpServletRequest request, SlingHttpServletResponse response) throws ServletException, IOException {
ResourceResolver resourceResolver = request.getResourceResolver();
String statement = StringUtils.removeStartIgnoreCase((String)request.getParameter("statement"), (String)"EXPLAIN ");
String language = request.getParameter("language");
language = LanguagesEnum.getValidLanguageName(language);
Session session = (Session)resourceResolver.adaptTo(Session.class);
try {
QueryManager queryManager = session.getWorkspace().getQueryManager();
JSONObject json = new JSONObject();
json.put("statement", (Object)statement);
json.put("language", (Object)language);
json.put("explain", (Object)this.explainQuery(queryManager, statement, language));
boolean collectExecutionTime = "true".equals(StringUtils.defaultIfEmpty((String)request.getParameter("executionTime"), (String)"false"));
boolean collectCount = "true".equals(StringUtils.defaultIfEmpty((String)request.getParameter("resultCount"), (String)"false"));
if (collectExecutionTime) {
json.put("heuristics", (Object)this.getHeuristics(queryManager, statement, language, collectCount));
}
response.setContentType("application/json");
response.getWriter().print(json.toString());
}
catch (RepositoryException e) {
log.error(e.getMessage());
response.sendError(500);
}
catch (JSONException e) {
log.error(e.getMessage());
response.sendError(500);
}
}
@Activate
private void activate(BundleContext context, Map<String, Object> config) {
this.bundleContext = context;
this.initializeParameters(config);
}
@Deactivate
private void deactivate() {
this.bundleContext = null;
this.logCollector.set(null);
}
@Modified
protected void update(BundleContext context, Map<String, Object> config) {
this.initializeParameters(config);
}
private void initializeParameters(Map<String, Object> config) {
loggers = this.toMap(PropertiesUtil.toStringArray((Object)config.get("log.logger-names"), (String[])new String[0]), "=", true, null);
logPattern = PropertiesUtil.toString((Object)config.get("log.pattern"), (String)"%msg%n");
messageCountLimit = PropertiesUtil.toInteger((Object)config.get("log.message-count-limit"), (int)100);
}
private Map<String, String> toMap(String[] values, String separator, boolean allowValuelessKeys, String defaultValue) {
LinkedHashMap<String, String> map = new LinkedHashMap<String, String>();
if (values == null || values.length < 1) {
return map;
}
for (String value : values) {
String[] tmp = StringUtils.split((String)value, (String)separator, (int)-1);
if (tmp.length == 1 && allowValuelessKeys) {
if (StringUtils.startsWith((String)value, (String)separator)) continue;
map.put(tmp[0], defaultValue);
continue;
}
if (tmp.length != 2) continue;
map.put(tmp[0], tmp[1]);
}
return map;
}
/*
* WARNING - Removed try catching itself - possible behaviour change.
*/
private String registerLogCollector() {
String collectorKey;
AtomicInteger atomicInteger = this.logCollectorRegCount;
synchronized (atomicInteger) {
int count = this.logCollectorRegCount.getAndIncrement();
if (count == 0 && loggers != null && !loggers.isEmpty()) {
if (this.logCollector.get() == null) {
QueryLogCollector collector = new QueryLogCollector(loggers, logPattern, messageCountLimit, ExplainQueryServlet.checkMDCSupport(this.bundleContext));
this.logCollector.set(collector);
}
ServiceRegistration reg = this.bundleContext.registerService(TurboFilter.class.getName(), (Object)this.logCollector.get(), null);
this.logCollectorReg.set(reg);
}
collectorKey = this.startCollection();
}
return collectorKey;
}
/*
* WARNING - Removed try catching itself - possible behaviour change.
*/
private void unregisterLogCollector(String collectorKey) {
AtomicInteger atomicInteger = this.logCollectorRegCount;
synchronized (atomicInteger) {
this.stopCollection(collectorKey);
int count = this.logCollectorRegCount.decrementAndGet();
if (count == 0) {
ServiceRegistration reg = this.logCollectorReg.getAndSet(null);
reg.unregister();
}
}
}
/*
* WARNING - Removed try catching itself - possible behaviour change.
*/
private JSONObject explainQuery(QueryManager queryManager, String statement, String language) throws RepositoryException, JSONException {
QueryResult queryResult;
JSONObject json = new JSONObject();
String collectorKey = null;
try {
collectorKey = this.registerLogCollector();
Query query = queryManager.createQuery("explain " + statement, language);
queryResult = query.execute();
}
finally {
if (collectorKey != null && this.logCollector != null && this.logCollector.get() != null) {
List<String> logs = this.logCollector.get().getLogs(collectorKey);
json.put("logs", logs);
if (logs.size() == this.logCollector.get().msgCountLimit) {
json.put("logsTruncated", true);
}
}
this.unregisterLogCollector(collectorKey);
}
RowIterator rows = queryResult.getRows();
Row firstRow = rows.nextRow();
String plan = firstRow.getValue("plan").getString();
json.put("plan", (Object)plan);
JSONArray indexes = new JSONArray();
boolean isProperty = false;
Matcher propertyMatcher = PROPERTY_INDEX_PATTERN.matcher(plan);
while (propertyMatcher.find()) {
String match = propertyMatcher.group(1);
if (!StringUtils.isNotBlank((String)match)) continue;
indexes.put((Object)StringUtils.stripToEmpty((String)match));
isProperty = true;
}
if (!isProperty) {
Matcher luceneMatcher = LUCENE_INDEX_PATTERN.matcher(plan);
while (luceneMatcher.find()) {
String match = luceneMatcher.group(1);
if (!StringUtils.isNotBlank((String)match)) continue;
indexes.put((Object)StringUtils.stripToEmpty((String)match));
}
}
if (indexes.length() > 0) {
json.put("propertyIndexes", (Object)indexes);
}
if (StringUtils.contains((String)plan, (String)" /* nodeType ")) {
indexes.put((Object)"nodeType");
json.put("propertyIndexes", (Object)indexes);
json.put("slow", true);
}
if (StringUtils.contains((String)plan, (String)" /* traverse ")) {
json.put("traversal", true);
json.put("slow", true);
}
if (StringUtils.contains((String)plan, (String)" /* aggregate ")) {
json.put("aggregate", true);
}
return json;
}
private JSONObject getHeuristics(QueryManager queryManager, String statement, String language, boolean getCount) throws RepositoryException, JSONException {
JSONObject json = new JSONObject();
long count = 0;
long countTime = 0;
Query query = queryManager.createQuery(statement, language);
long start = System.currentTimeMillis();
QueryResult queryResult = query.execute();
long executionTime = System.currentTimeMillis() - start;
start = System.currentTimeMillis();
NodeIterator nodes = queryResult.getNodes();
long getNodesTime = System.currentTimeMillis() - start;
if (getCount) {
while (nodes.hasNext()) {
nodes.next();
++count;
}
countTime = System.currentTimeMillis() - start;
json.put("count", count);
json.put("countTime", countTime);
}
json.put("executionTime", executionTime);
json.put("getNodesTime", getNodesTime);
json.put("totalTime", executionTime + getNodesTime + countTime);
return json;
}
private String startCollection() {
String collectorKey = UUID.randomUUID().toString();
MDC.put((String)"collectorKey", (String)collectorKey);
return collectorKey;
}
private void stopCollection(String key) {
MDC.remove((String)key);
if (key != null && this.logCollector != null && this.logCollector.get() != null) {
this.logCollector.get().stopCollection(key);
}
}
private static boolean checkMDCSupport(BundleContext context) {
Version versionWithMDCSupport = new Version(1, 0, 9);
for (Bundle b : context.getBundles()) {
if (!"org.apache.jackrabbit.oak-core".equals(b.getSymbolicName())) continue;
return versionWithMDCSupport.compareTo(b.getVersion()) <= 0;
}
return true;
}
static {
loggers = new HashMap<String, String>();
}
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 = QueryLogCollector.createLayout(pattern);
this.mdcEnabled = mdcEnabled;
if (!mdcEnabled) {
log.debug("Current Oak version does not provide MDC. Explain log would have some extra entries");
}
}
public FilterReply decide(Marker marker, ch.qos.logback.classic.Logger logger, Level level, String format, Object[] params, Throwable t) {
String collectorKey = MDC.get((String)"collectorKey");
if (collectorKey == null) {
return FilterReply.NEUTRAL;
}
if (!this.acceptLogStatement(logger.getName())) {
return FilterReply.NEUTRAL;
}
if (format == null) {
return FilterReply.ACCEPT;
}
LoggingEvent logEvent = new LoggingEvent(ch.qos.logback.classic.Logger.FQCN, logger, level, format, t, params);
this.log(collectorKey, (ILoggingEvent)logEvent);
return FilterReply.NEUTRAL;
}
public List<String> getLogs(String collectorKey) {
List<ILoggingEvent> eventList = this.logEvents.get(collectorKey);
if (eventList == null) {
return Collections.emptyList();
}
ArrayList<String> result = new ArrayList<String>(eventList.size());
for (ILoggingEvent e : eventList) {
result.add(this.layout.doLayout((Object)e));
}
return result;
}
public void stopCollection(String key) {
this.logEvents.remove(key);
}
private void log(String collectorKey, ILoggingEvent e) {
List<ILoggingEvent> eventList = this.logEvents.get(collectorKey);
if (eventList == null) {
eventList = new ArrayList<ILoggingEvent>();
this.logEvents.put(collectorKey, eventList);
}
if (eventList.size() < this.msgCountLimit) {
eventList.add(e);
}
}
private boolean acceptLogStatement(String name) {
for (Map.Entry<String, String> entry : this.loggers.entrySet()) {
if (!name.startsWith(entry.getKey())) continue;
if (!this.mdcEnabled) {
return true;
}
if (this.mdcEnabled && entry.getValue() == null) {
return true;
}
if (this.mdcEnabled && entry.getValue() != null && MDC.get((String)entry.getValue()) != null) {
return true;
}
return false;
}
return false;
}
private static Layout<ILoggingEvent> createLayout(String pattern) {
PatternLayout pl = new PatternLayout();
pl.setPattern(pattern);
pl.setOutputPatternAsHeader(false);
pl.setContext((Context)((LoggerContext)LoggerFactory.getILoggerFactory()));
pl.start();
return pl;
}
}
private static enum LanguagesEnum {
SQL("sql"),
SQL2("JCR-SQL2"),
XPATH("xpath");
private String label;
private LanguagesEnum(String label) {
this.label = label;
}
public static String getValidLanguageName(String language) {
String result = "";
if (language != null && language.trim().length() > 0) {
for (LanguagesEnum validLanguage : LanguagesEnum.values()) {
if (!validLanguage.label.equalsIgnoreCase(language.trim())) continue;
result = validLanguage.label;
break;
}
}
return result;
}
}
}