commit 88f3d3aa855465381b104bf5883f8c84647fe210
author Chetan Mehrotra <chetanm@apache.org> Mon Feb 15 13:59:16 2016 +0000
committer Chetan Mehrotra <chetanm@apache.org> Mon Feb 15 13:59:16 2016 +0000
tree 1a32b9d7029a7ef9984a2d493bab0f875bcc673e
parent c6dad281d70457a496b993fbd1fa90f528df963c

SLING-5507 - Collect more details around query execution

Fix an issue where only query recording was done instead of multiple in a given request. As a fix the logic now does not rely on MDC to detect query boundaries

git-svn-id: https://svn.apache.org/repos/asf/sling/trunk/contrib/extensions/tracer@1730533 13f79535-47bb-0310-9956-ffa450edef68

src/main/java/org/apache/sling/tracer/internal/JSONRecording.java

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 a88a250..21d99d4 100644
--- a/src/main/java/org/apache/sling/tracer/internal/JSONRecording.java
+++ b/src/main/java/org/apache/sling/tracer/internal/JSONRecording.java
@@ -49,7 +49,6 @@
 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;
 
@@ -323,27 +322,17 @@
     }
 
     private class QueryLogCollector {
-        /**
-         * The MDC key is used in org.apache.jackrabbit.oak.query.QueryEngineImpl
-         */
-        static final String MDC_QUERY_ID = "oak.query.id";
         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;
-            }
+            //Assuming in a series of log statement from query package we see 'query'
+            //and then 'plan' then once both are not null then it means that one query
+            //execution is complete and we push the entry and reset the state
+            //This is done as we do not have a definitive way to determine when
+            //a given query processing is done
+            attemptQueryEntry();
 
             //TODO Query time. Change Oak to provide this information via some
             //dedicated Audit logging such that below reliance on impl details
@@ -383,7 +372,11 @@
             return null;
         }
 
-        public void addQueryEntry(){
+        /**
+         * Checks if both plan and query are determined. If yes then pushes them to list
+         * and resets the state.
+         */
+        public void attemptQueryEntry(){
             if (query != null && plan != null){
                 queries.add(new QueryEntry(nullSafeTrim(query), nullSafeTrim(plan), caller));
                 plan = query = null;
@@ -392,7 +385,7 @@
 
         public void done(){
             //Push any last pending entry i.e. last query
-            addQueryEntry();
+            attemptQueryEntry();
         }
     }