You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@sling.apache.org by ro...@apache.org on 2017/10/18 23:26:11 UTC
[sling-org-apache-sling-tracer] 27/49: SLING-5507 - Collect more
details around query execution
This is an automated email from the ASF dual-hosted git repository.
rombert pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/sling-org-apache-sling-tracer.git
commit 0fa854e68d58f5e6ff8e5ce30994ff5b3a05e31a
Author: Chetan Mehrotra <ch...@apache.org>
AuthorDate: Wed Feb 10 16:45:41 2016 +0000
SLING-5507 - Collect more details around query execution
git-svn-id: https://svn.apache.org/repos/asf/sling/trunk@1729651 13f79535-47bb-0310-9956-ffa450edef68
---
.../apache/sling/tracer/internal/CallerFinder.java | 69 +++++++++++++
.../sling/tracer/internal/JSONRecording.java | 110 ++++++++++++++++++---
.../sling/tracer/internal/CallerFinderTest.java | 96 ++++++++++++++++++
.../sling/tracer/internal/JSONRecordingTest.java | 15 ++-
4 files changed, 276 insertions(+), 14 deletions(-)
diff --git a/src/main/java/org/apache/sling/tracer/internal/CallerFinder.java b/src/main/java/org/apache/sling/tracer/internal/CallerFinder.java
new file mode 100644
index 0000000..f08e8e7
--- /dev/null
+++ b/src/main/java/org/apache/sling/tracer/internal/CallerFinder.java
@@ -0,0 +1,69 @@
+/*
+ * 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.sling.tracer.internal;
+
+import java.util.Arrays;
+import java.util.Collections;
+import java.util.List;
+
+import javax.annotation.CheckForNull;
+
+import com.google.common.collect.Iterators;
+import com.google.common.collect.PeekingIterator;
+
+/**
+ * Utility to find out the real caller by excluding stack elements belonging to
+ * API classes. Say for a query it would exclude the call stack which is part of Oak
+ * or Sling Engine
+ */
+class CallerFinder {
+ private final String[] apiPkgs;
+
+ public CallerFinder(String[] apiPkgs) {
+ this.apiPkgs = apiPkgs;
+ }
+
+ @CheckForNull
+ public StackTraceElement determineCaller(StackTraceElement[] stack) {
+ if (stack == null) {
+ return null;
+ }
+
+ //Reverse the stack trace so as to start from bottom
+ List<StackTraceElement> stackList = Arrays.asList(stack);
+ Collections.reverse(stackList);
+ PeekingIterator<StackTraceElement> pit = Iterators.peekingIterator(stackList.iterator());
+ while (pit.hasNext()) {
+ StackTraceElement current = pit.next();
+
+ //now scan each element and check if the *next* stack element belongs to any
+ //api package. If yes then current stack would be the caller
+ if (pit.hasNext()) {
+ StackTraceElement next = pit.peek();
+ for (String pkg : apiPkgs) {
+ if (next.getClassName().startsWith(pkg)) {
+ return current;
+ }
+ }
+ }
+ }
+ return null;
+ }
+}
diff --git a/src/main/java/org/apache/sling/tracer/internal/JSONRecording.java b/src/main/java/org/apache/sling/tracer/internal/JSONRecording.java
index b1e76be..c0aec8a 100644
--- a/src/main/java/org/apache/sling/tracer/internal/JSONRecording.java
+++ b/src/main/java/org/apache/sling/tracer/internal/JSONRecording.java
@@ -48,23 +48,31 @@ import org.apache.sling.commons.json.JSONException;
import org.apache.sling.commons.json.io.JSONWriter;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
+import org.slf4j.MDC;
import org.slf4j.helpers.FormattingTuple;
import org.slf4j.helpers.MessageFormatter;
import static com.google.common.base.Preconditions.checkArgument;
class JSONRecording implements Recording, Comparable<JSONRecording> {
+ private static final String[] QUERY_API_PKGS = {
+ "org.apache.sling.resourceresolver", //Sling package would come first in stack so listed first
+ "org.apache.jackrabbit.oak"
+ };
private static final Logger log = LoggerFactory.getLogger(JSONRecording.class);
+ public static final String OAK_QUERY_PKG = "org.apache.jackrabbit.oak.query";
private final String method;
private final String requestId;
private final String uri;
private final boolean compress;
- private final List<String> queries = new ArrayList<String>();
+ private final List<QueryEntry> queries = new ArrayList<QueryEntry>();
private final List<LogEntry> logs = new ArrayList<LogEntry>();
private RequestProgressTracker tracker;
private byte[] json;
private final long start = System.currentTimeMillis();
private long timeTaken;
+ private final QueryLogCollector queryCollector = new QueryLogCollector();
+ private final CallerFinder queryCallerFinder = new CallerFinder(QUERY_API_PKGS);
public JSONRecording(String requestId, HttpServletRequest r, boolean compress) {
this.requestId = requestId;
@@ -117,10 +125,8 @@ class JSONRecording implements Recording, Comparable<JSONRecording> {
@Override
public void log(TracerConfig tc, Level level, String logger, FormattingTuple tuple) {
- Object[] params = tuple.getArgArray();
- if (TracerContext.QUERY_LOGGER.equals(logger)
- && params != null && params.length == 2) {
- queries.add((String) params[1]);
+ if (logger.startsWith(OAK_QUERY_PKG)) {
+ queryCollector.record(level, logger, tuple);
}
logs.add(new LogEntry(level, logger, tuple));
}
@@ -177,12 +183,8 @@ class JSONRecording implements Recording, Comparable<JSONRecording> {
jw.endArray();
}
- jw.key("queries");
- jw.array();
- for (String q : queries) {
- jw.value(q);
- }
- jw.endArray();
+ queryCollector.done();
+ addJson(jw, "queries", queries);
addJson(jw, "logs", logs);
jw.endObject();
@@ -274,4 +276,90 @@ class JSONRecording implements Recording, Comparable<JSONRecording> {
}
}
+ private static class QueryEntry implements JsonEntry {
+ final String query;
+ final String plan;
+ final String caller;
+
+ private QueryEntry(String query, String plan, String caller) {
+ this.query = query;
+ this.plan = plan;
+ this.caller = caller;
+ }
+
+ @Override
+ public void toJson(JSONWriter jw) throws JSONException {
+ jw.key("query").value(query);
+ jw.key("plan").value(plan);
+ jw.key("caller").value(caller);
+ }
+ }
+
+ private class QueryLogCollector {
+ /**
+ * The MDC key is used in org.apache.jackrabbit.oak.query.QueryEngineImpl
+ */
+ static final String MDC_QUERY_ID = "oak.query.id";
+ static final String QE_LOGGER = "org.apache.jackrabbit.oak.query.QueryImpl";
+ String query;
+ String plan;
+ String id;
+ String caller;
+
+ public void record(Level level, String logger, FormattingTuple tuple) {
+ String idFromMDC = MDC.get(MDC_QUERY_ID);
+
+ //Use the query id to detect change of query execution
+ //i.e. once query gets executed for current thread and next
+ //query start it would cause the id to change. That would
+ //be a trigger to finish up on current query collection and
+ //switch to new one
+ if (idFromMDC != null && !idFromMDC.equals(id)) {
+ addQueryEntry();
+ id = idFromMDC;
+ }
+
+ String msg = tuple.getMessage();
+ if (Level.DEBUG == level
+ && QE_LOGGER.equals(logger)
+ && msg != null){
+
+ //The Log stmt are as present in org.apache.jackrabbit.oak.query.QueryImpl
+ if (msg.startsWith("query execute ")){
+ query = msg.substring("query execute ".length());
+ caller = determineCaller();
+ } else if (msg.startsWith("query plan ")){
+ plan = msg.substring("query plan ".length());
+ }
+ }
+ }
+
+ private String determineCaller() {
+ StackTraceElement caller = queryCallerFinder.determineCaller(Thread.currentThread().getStackTrace());
+ if (caller != null) {
+ return caller.toString();
+ }
+ return null;
+ }
+
+ public void addQueryEntry(){
+ if (query != null){
+ queries.add(new QueryEntry(safeTrim(query), safeTrim(plan), caller));
+ plan = query = null;
+ }
+ }
+
+ public void done(){
+ //Push any last pending entry i.e. last query
+ addQueryEntry();
+ }
+
+ private String safeTrim(String s){
+ if(s == null){
+ return "";
+ }
+ return s.trim();
+ }
+ }
+
}
diff --git a/src/test/java/org/apache/sling/tracer/internal/CallerFinderTest.java b/src/test/java/org/apache/sling/tracer/internal/CallerFinderTest.java
new file mode 100644
index 0000000..51d4ba2
--- /dev/null
+++ b/src/test/java/org/apache/sling/tracer/internal/CallerFinderTest.java
@@ -0,0 +1,96 @@
+/*
+ * 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.sling.tracer.internal;
+
+import org.junit.Test;
+
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertNotNull;
+import static org.junit.Assert.assertNull;
+
+public class CallerFinderTest {
+
+ @Test
+ public void determineCallerSingle() throws Exception{
+ CallerFinder cf = new CallerFinder(new String[] {"o.a.s", "o.a.j.o"});
+ StackTraceElement[] stack = createStack(
+ "o.a.j.o.a",
+ "o.a.j.o.b",
+ "c.a.g.w",
+ "o.e.j",
+ "o.e.j",
+ "o.e.j"
+ );
+
+ StackTraceElement caller = cf.determineCaller(stack);
+ assertNotNull(caller);
+ assertEquals("c.a.g.w", caller.getClassName());
+ }
+
+ @Test
+ public void determineCallerMultipleApi() throws Exception{
+ CallerFinder cf = new CallerFinder(new String[] {"o.a.s", "o.a.j.o"});
+ StackTraceElement[] stack = createStack(
+ "o.a.j.o.a",
+ "o.a.j.o.b",
+ "o.a.s.a",
+ "o.a.s.b",
+ "c.a.g.w",
+ "o.e.j",
+ "o.e.j",
+ "o.e.j"
+ );
+
+ StackTraceElement caller = cf.determineCaller(stack);
+ assertNotNull(caller);
+ assertEquals("c.a.g.w", caller.getClassName());
+
+ stack = createStack(
+ "o.a.j.o.a",
+ "o.a.j.o.b",
+ "o.a.s.a",
+ "o.a.s.b",
+ "c.a.g.w",
+ "o.e.j",
+ "o.e.j",
+ "o.e.j"
+ );
+
+ cf = new CallerFinder(new String[] {"o.a.j.o"});
+ caller = cf.determineCaller(stack);
+ assertNotNull(caller);
+ assertEquals("o.a.s.a", caller.getClassName());
+
+ }
+
+ @Test
+ public void nullInput() throws Exception{
+ CallerFinder cf = new CallerFinder(new String[] {"o.a.s", "o.a.j.o"});
+ assertNull(cf.determineCaller(null));
+ }
+
+ private static StackTraceElement[] createStack(String ... stack){
+ StackTraceElement[] result = new StackTraceElement[stack.length];
+ for (int i = 0; i < stack.length; i++) {
+ result[i] = new StackTraceElement(stack[i], "foo", null, 0);
+ }
+ return result;
+ }
+}
diff --git a/src/test/java/org/apache/sling/tracer/internal/JSONRecordingTest.java b/src/test/java/org/apache/sling/tracer/internal/JSONRecordingTest.java
index ac8ad3c..e0a2476 100644
--- a/src/test/java/org/apache/sling/tracer/internal/JSONRecordingTest.java
+++ b/src/test/java/org/apache/sling/tracer/internal/JSONRecordingTest.java
@@ -25,7 +25,9 @@ import javax.servlet.http.HttpServletRequest;
import ch.qos.logback.classic.Level;
import org.apache.sling.commons.json.JSONObject;
+import org.junit.Ignore;
import org.junit.Test;
+import org.slf4j.MDC;
import org.slf4j.helpers.FormattingTuple;
import org.slf4j.helpers.MessageFormatter;
@@ -37,6 +39,8 @@ import static org.mockito.Mockito.mock;
import static org.mockito.Mockito.when;
public class JSONRecordingTest {
+ static final String MDC_QUERY_ID = "oak.query.id";
+ static String QE_LOGGER = "org.apache.jackrabbit.oak.query.QueryImpl";
private HttpServletRequest request = mock(HttpServletRequest.class);
private TracerConfig tc = new TracerConfig(TracerContext.QUERY_LOGGER, Level.INFO);
@@ -48,8 +52,9 @@ public class JSONRecordingTest {
when(request.getMethod()).thenReturn("GET");
JSONRecording r = new JSONRecording("abc", request, true);
- r.log(tc, Level.INFO, TracerContext.QUERY_LOGGER, MessageFormatter.arrayFormat("foo bar", new Object[]{"x" , "y"}));
- r.log(tc, Level.INFO, TracerContext.QUERY_LOGGER, MessageFormatter.arrayFormat("foo bar", new Object[]{"x" , "z"}));
+ MDC.put(MDC_QUERY_ID, "1");
+ r.log(tc, Level.DEBUG, QE_LOGGER, tuple("query execute SELECT FOO"));
+ r.log(tc, Level.DEBUG, QE_LOGGER, tuple("query plan FOO PLAN"));
r.done();
r.render(sw);
@@ -58,7 +63,7 @@ public class JSONRecordingTest {
assertEquals("GET", json.get("method"));
assertTrue(json.has("time"));
assertTrue(json.has("timestamp"));
- assertEquals(2, json.getJSONArray("queries").length());
+ assertEquals(1, json.getJSONArray("queries").length());
}
@Test
@@ -103,4 +108,8 @@ public class JSONRecordingTest {
JSONObject l3 = json.getJSONArray("logs").getJSONObject(2);
assertNotNull(l3.get("exception"));
}
+
+ private static FormattingTuple tuple(String msg){
+ return MessageFormatter.format(msg, null);
+ }
}
--
To stop receiving notification emails like this one, please contact
"commits@sling.apache.org" <co...@sling.apache.org>.