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 <[email protected]> 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 "[email protected]" <[email protected]>.
