Implement Query Split Counting (#537)

 Implement query split logging

CHANGELOG.md

@@ -10,6 +10,14 @@ Current
 
 ### Added:
 
+- [Implement Query Split Logging](https://github.com/yahoo/fili/pull/537)
+    * Include metrics in logging to allow for better evaluation of the impact of caching for split queries.
+        - Currently there is only a binary flag (`BardQueryInfo.cached`) that is inconsistently set for split queries
+        - Three new metrics are added
+            1. Number of split queries satisfied by cache
+            2. Number of split queries actually sent to the fact store. (not satisfied by cache)
+            3. Number of weight-checked queries
+
 - [Documentation that `Dimension::getFieldByName` should throw an `IllegalArgumentException` if there is no field with the passed in name](https://github.com/yahoo/fili/pull/547)
 
 - [Evaluate format type from both URI and Accept header](https://github.com/yahoo/fili/pull/495)

fili-core/src/main/java/com/yahoo/bard/webservice/logging/LogBlock.java

@@ -36,6 +36,17 @@ public void add(LogInfo phase) {
         body.put(phase.getName(), phase);
     }
 
+    /**
+     * Return a part of logging information in this LogBlock.
+     *
+     * @param name  Name of a {@link LogInfo} object to be returned
+     *
+     * @return a part of logging information in this LogBlock
+     */
+    public LogInfo get(String name) {
+        return body.get(name);
+    }
+
     /**
      * Create a new LogBlock with the same body but updated uuid.
      *

fili-core/src/main/java/com/yahoo/bard/webservice/logging/RequestLog.java

@@ -306,7 +306,7 @@ public static void stopMostRecentTimer() {
     /**
      * Record logging information in the logging context.
      *
-     * @param logPhase  the name of the class destined to hold this logging information
+     * @param logPhase  The name of the class destined to hold this logging information
      *
      * @see LogBlock
      */
@@ -321,6 +321,35 @@ public static void record(LogInfo logPhase) {
         }
     }
 
+    /**
+     * Retrieve logging information in the logging context.
+     *
+     * @param cls  The class destined to hold this logging information
+     *
+     * @return the logging information in the logging context
+     *
+     * @see LogBlock
+     */
+    public static LogInfo retrieve(Class cls) {
+        RequestLog requestLog = RLOG.get();
+        if (requestLog == null) {
+            String message = String.format(
+                    "Attempted to retrieve log info while request log object was uninitialized: %s",
+                    cls.getSimpleName()
+            );
+            LOG.error(message);
+            throw new IllegalStateException(message);
+        }
+
+        LogInfo logInfo = requestLog.info.get(cls.getSimpleName());
+        if (logInfo == null) {
+            String message = ErrorMessageFormat.RESOURCE_RETRIEVAL_FAILURE.format(cls.getSimpleName());
+            LOG.error(message);
+            throw new IllegalStateException(message);
+        }
+        return logInfo;
+    }
+
     /**
      * Write the request log object of the current thread as JSON.
      * The thread's request log is cleared after a call to this method.

fili-core/src/main/java/com/yahoo/bard/webservice/logging/blocks/BardQueryInfo.java

@@ -3,25 +3,95 @@
 package com.yahoo.bard.webservice.logging.blocks;
 
 import com.yahoo.bard.webservice.logging.LogInfo;
+import com.yahoo.bard.webservice.logging.RequestLog;
+import com.yahoo.bard.webservice.web.ErrorMessageFormat;
 
 import com.fasterxml.jackson.annotation.JsonAutoDetect;
 
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+import java.util.AbstractMap;
+import java.util.Map;
+import java.util.concurrent.atomic.AtomicInteger;
+import java.util.stream.Collectors;
+import java.util.stream.Stream;
+
 /**
  * Main log of a request served by the TablesServlet.
  */
 @JsonAutoDetect(fieldVisibility = JsonAutoDetect.Visibility.ANY)
 public class BardQueryInfo implements LogInfo {
+    private static final Logger LOG = LoggerFactory.getLogger(BardQueryInfo.class);
+    private static final String WEIGHT_CHECK = "weight check queries count";
+    private static final String FACT_QUERIES = "fact queries count";
+    private static final String FACT_QUERY_CACHE_HIT  = "fact query cache hit count";
+
+    protected static final Map<String, AtomicInteger> QUERY_COUNTER = Stream.of(
+            new AbstractMap.SimpleImmutableEntry<>(WEIGHT_CHECK, new AtomicInteger()),
+            new AbstractMap.SimpleImmutableEntry<>(FACT_QUERIES, new AtomicInteger()),
+            new AbstractMap.SimpleImmutableEntry<>(FACT_QUERY_CACHE_HIT, new AtomicInteger())
+    ).collect(Collectors.toMap(
+            AbstractMap.SimpleImmutableEntry::getKey,
+            AbstractMap.SimpleImmutableEntry::getValue
+    ));
+
     protected final String type;
-    protected final boolean cached;
 
     /**
      * Constructor.
      *
-     * @param type  Type of Bard query
-     * @param cached  Indicates if the query was served from the data cache or not
+     * @param queryType  Type of Bard query
+     */
+    public BardQueryInfo(String queryType) {
+        this.type = queryType;
+    }
+
+    /**
+     * Increments the number of fact queries.
+     */
+    public static void incrementCountFactHits() {
+        getBardQueryInfo().incrementCountFor(BardQueryInfo.FACT_QUERIES);
+    }
+
+    /**
+     * Increments the number of cache-hit queries.
+     */
+    public static void incrementCountCacheHits() {
+        getBardQueryInfo().incrementCountFor(BardQueryInfo.FACT_QUERY_CACHE_HIT);
+    }
+
+    /**
+     * Increments the number of weight check queries.
+     */
+    public static void incrementCountWeightCheck() {
+        getBardQueryInfo().incrementCountFor(BardQueryInfo.WEIGHT_CHECK);
+    }
+
+    /**
+     * Retrieves {@link com.yahoo.bard.webservice.logging.blocks.BardQueryInfo} from
+     * {@link com.yahoo.bard.webservice.logging.RequestLog}.
+     *
+     * @return {@link com.yahoo.bard.webservice.logging.blocks.BardQueryInfo} from
+     * {@link com.yahoo.bard.webservice.logging.RequestLog}
+     */
+    protected static BardQueryInfo getBardQueryInfo() {
+        return ((BardQueryInfo) RequestLog.retrieve(BardQueryInfo.class));
+    }
+
+    /**
+     * Increments the number of a type of query, whose possible type are all specified in
+     * {@link com.yahoo.bard.webservice.logging.blocks.BardQueryInfo}.
+     *
+     * @param queryType  The type of the query
      */
-    public BardQueryInfo(String type, boolean cached) {
-        this.type = type;
-        this.cached = cached;
+    protected static void incrementCountFor(String queryType) {
+        AtomicInteger count = QUERY_COUNTER.get(queryType);
+        if (count == null) {
+            String message = ErrorMessageFormat.RESOURCE_RETRIEVAL_FAILURE.format(queryType);
+            LOG.error(message);
+            throw new IllegalArgumentException(message);
+        }
+        count.incrementAndGet();
     }
 }

fili-core/src/main/java/com/yahoo/bard/webservice/web/ErrorMessageFormat.java

@@ -154,7 +154,7 @@ public enum ErrorMessageFormat implements MessageFormatter {
     ),
     LOG_UNABLE_TO_DESERIALIZE("Unable to deserialize results for job %s from %s"),
 
-    RESOURCE_RETRIEVAL_FAILURE("Unable to retrieve the resource for given resource name: %s. %s"),
+    RESOURCE_RETRIEVAL_FAILURE("Unable to retrieve the resource for given resource name: %s."),
     RESOURCE_STORAGE_FAILURE("Unable to store the resource for resource name %s. %s"),
     RESOURCE_DELETION_FAILURE("Unable to delete the resource for resource name %s. %s"),
 

fili-core/src/main/java/com/yahoo/bard/webservice/web/endpoints/DataServlet.java

@@ -226,7 +226,7 @@ private void logRequestMetrics(DataApiRequest request, Boolean readCache, DruidQ
         LogicalTable table = request.getTable();
         REGISTRY.meter("request.logical.table." + table.getName() + "." + table.getGranularity()).mark();
 
-        RequestLog.record(new BardQueryInfo(druidQuery.getQueryType().toJson(), false));
+        RequestLog.record(new BardQueryInfo(druidQuery.getQueryType().toJson()));
         RequestLog.record(
                 new DataRequest(
                         table,

fili-core/src/main/java/com/yahoo/bard/webservice/web/handlers/AsyncWebServiceRequestHandler.java

@@ -8,6 +8,7 @@
 import com.yahoo.bard.webservice.druid.client.SuccessCallback;
 import com.yahoo.bard.webservice.druid.model.query.DruidAggregationQuery;
 import com.yahoo.bard.webservice.logging.RequestLog;
+import com.yahoo.bard.webservice.logging.blocks.BardQueryInfo;
 import com.yahoo.bard.webservice.web.DataApiRequest;
 import com.yahoo.bard.webservice.web.responseprocessors.LoggingContext;
 import com.yahoo.bard.webservice.web.responseprocessors.ResponseProcessor;
@@ -51,6 +52,7 @@ public void invoke(JsonNode rootNode) {
         HttpErrorCallback error = response.getErrorCallback(druidQuery);
         FailureCallback failure = response.getFailureCallback(druidQuery);
 
+        BardQueryInfo.incrementCountFactHits();
         druidWebService.postDruidQuery(context, success, error, failure, druidQuery);
         return true;
     }

fili-core/src/main/java/com/yahoo/bard/webservice/web/handlers/CacheRequestHandler.java

@@ -84,14 +84,13 @@ public boolean handleRequest(
                 if (jsonResult != null) {
                     try {
                         if (context.getNumberOfOutgoing().decrementAndGet() == 0) {
-                            RequestLog.record(new BardQueryInfo(druidQuery.getQueryType().toJson(), true));
+                            BardQueryInfo.incrementCountCacheHits();
                             RequestLog.stopTiming(REQUEST_WORKFLOW_TIMER);
                         }
 
                         if (context.getNumberOfIncoming().decrementAndGet() == 0) {
                             RequestLog.startTiming(RESPONSE_WORKFLOW_TIMER);
                         }
-
                         CACHE_HITS.mark(1);
                         RequestLog logCtx = RequestLog.dump();
                         nextResponse.processResponse(

fili-core/src/main/java/com/yahoo/bard/webservice/web/handlers/CacheV2RequestHandler.java

@@ -100,14 +100,13 @@ public boolean handleRequest(
                     ) {
                         try {
                             if (context.getNumberOfOutgoing().decrementAndGet() == 0) {
-                                RequestLog.record(new BardQueryInfo(druidQuery.getQueryType().toJson(), true));
+                                BardQueryInfo.incrementCountCacheHits();
                                 RequestLog.stopTiming(REQUEST_WORKFLOW_TIMER);
                             }
 
                             if (context.getNumberOfIncoming().decrementAndGet() == 0) {
                                 RequestLog.startTiming(RESPONSE_WORKFLOW_TIMER);
                             }
-
                             CACHE_HITS.mark(1);
                             RequestLog logCtx = RequestLog.dump();
                             nextResponse.processResponse(

fili-core/src/main/java/com/yahoo/bard/webservice/web/handlers/EtagCacheRequestHandler.java

@@ -90,7 +90,7 @@ public boolean handleRequest(
                             );
 
                     if (context.getNumberOfOutgoing().decrementAndGet() == 0) {
-                        RequestLog.record(new BardQueryInfo(druidQuery.getQueryType().toJson(), true));
+                        BardQueryInfo.incrementCountCacheHits();
                         RequestLog.stopTiming(REQUEST_WORKFLOW_TIMER);
                     }
 

fili-core/src/main/java/com/yahoo/bard/webservice/web/handlers/WeightCheckRequestHandler.java

@@ -8,6 +8,7 @@
 import com.yahoo.bard.webservice.druid.client.SuccessCallback;
 import com.yahoo.bard.webservice.druid.model.query.DruidAggregationQuery;
 import com.yahoo.bard.webservice.druid.model.query.Granularity;
+import com.yahoo.bard.webservice.logging.blocks.BardQueryInfo;
 import com.yahoo.bard.webservice.web.DataApiRequest;
 import com.yahoo.bard.webservice.web.ErrorMessageFormat;
 import com.yahoo.bard.webservice.web.responseprocessors.ResponseProcessor;
@@ -71,6 +72,7 @@ public boolean handleRequest(
             return next.handleRequest(context, request, druidQuery, response);
         }
 
+        BardQueryInfo.incrementCountWeightCheck();
         final WeightCheckResponseProcessor weightCheckResponse = new WeightCheckResponseProcessor(response);
         final DruidAggregationQuery<?> weightEvaluationQuery = queryWeightUtil.makeWeightEvaluationQuery(druidQuery);
         Granularity granularity = druidQuery.getInnermostQuery().getGranularity();

fili-core/src/test/groovy/com/yahoo/bard/webservice/logging/blocks/BardQueryInfoSpec.groovy

@@ -0,0 +1,68 @@
+// Copyright 2017 Yahoo Inc.
+// Licensed under the terms of the Apache license. Please see LICENSE.md file distributed with this work for terms.
+package com.yahoo.bard.webservice.logging.blocks
+
+import com.yahoo.bard.webservice.web.ErrorMessageFormat
+import spock.lang.Specification
+import spock.lang.Unroll
+
+class BardQueryInfoSpec extends Specification {
+    BardQueryInfo bardQueryInfo
+
+    def setup() {
+        bardQueryInfo = BardQueryInfoUtils.initializeBardQueryInfo()
+    }
+
+    def cleanup() {
+        BardQueryInfoUtils.resetBardQueryInfo()
+    }
+
+    def "getBardQueryInfo() returns registered BardQueryInfo instance"() {
+        expect:
+        BardQueryInfo.getBardQueryInfo() == bardQueryInfo
+    }
+
+    @Unroll
+    def "incrementCountFor(#queryType) increments count of #queryType by 1"() {
+        expect: "count for #queryType is 0"
+        BardQueryInfo.QUERY_COUNTER.get(queryType).get() == 0
+
+        when: "calling incrementCountFor(#queryType)"
+        BardQueryInfo.incrementCountFor(queryType)
+
+        then: "count of #queryType is incremented by 1"
+        BardQueryInfo.QUERY_COUNTER.get(queryType).get() == 1
+
+        where:
+        queryType                          | _
+        BardQueryInfo.WEIGHT_CHECK         | _
+        BardQueryInfo.FACT_QUERIES         | _
+        BardQueryInfo.FACT_QUERY_CACHE_HIT | _
+    }
+
+    def "incrementCountFor(String) throws IllegalArgumentException on non-existing query type"() {
+        when: "BardQueryInfo is given an unknown query type"
+        BardQueryInfo.incrementCountFor("nonExistingQueryType")
+
+        then: "IllegalArgumentException is thrown with exception message"
+        IllegalArgumentException illegalArgumentException = thrown()
+        illegalArgumentException.message == ErrorMessageFormat.RESOURCE_RETRIEVAL_FAILURE.format("nonExistingQueryType")
+    }
+
+    def "incrementCount*() methods increment their corresponding query type counts by 1"() {
+        expect: "all query counts are 0"
+        BardQueryInfo.QUERY_COUNTER.get(BardQueryInfo.WEIGHT_CHECK).get() == 0
+        BardQueryInfo.QUERY_COUNTER.get(BardQueryInfo.FACT_QUERIES).get() == 0
+        BardQueryInfo.QUERY_COUNTER.get(BardQueryInfo.FACT_QUERY_CACHE_HIT).get() == 0
+
+        when: "calling incrementCount*() methods for all query types"
+        BardQueryInfo.incrementCountWeightCheck()
+        BardQueryInfo.incrementCountFactHits()
+        BardQueryInfo.incrementCountCacheHits()
+
+        then: "counts of all query types are incremented by 1"
+        BardQueryInfo.QUERY_COUNTER.get(BardQueryInfo.WEIGHT_CHECK).get() == 1
+        BardQueryInfo.QUERY_COUNTER.get(BardQueryInfo.FACT_QUERIES).get() == 1
+        BardQueryInfo.QUERY_COUNTER.get(BardQueryInfo.FACT_QUERY_CACHE_HIT).get() == 1
+    }
+}

fili-core/src/test/groovy/com/yahoo/bard/webservice/logging/blocks/BardQueryInfoUtils.groovy

@@ -0,0 +1,34 @@
+// Copyright 2017 Yahoo Inc.
+// Licensed under the terms of the Apache license. Please see LICENSE.md file distributed with this work for terms.
+package com.yahoo.bard.webservice.logging.blocks
+
+import com.yahoo.bard.webservice.logging.RequestLog
+
+import java.util.concurrent.atomic.AtomicInteger
+
+class BardQueryInfoUtils {
+    /**
+     * Constructs and returns a testing BardQueryInfo instance without a query type.
+     *
+     * @return a testing BardQueryInfo instance without a query type
+     */
+    static BardQueryInfo initializeBardQueryInfo() {
+        resetBardQueryInfo()
+        BardQueryInfo bardQueryInfo = new BardQueryInfo(null)
+        RequestLog.getId() // initialize RequestLog
+        RequestLog.record(bardQueryInfo)
+        return bardQueryInfo
+    }
+
+    /**
+     * Resets counts of all query types in BardQueryInfo.
+     */
+    static void resetBardQueryInfo() {
+        RequestLog.dump()
+
+        // reset counts of all query types after each individual test
+        for (Map.Entry<String, AtomicInteger> entry : BardQueryInfo.QUERY_COUNTER.entrySet()) {
+            entry.value = new AtomicInteger()
+        }
+    }
+}

fili-core/src/test/groovy/com/yahoo/bard/webservice/logging/blocks/DruidFilterInfoSpec.groovy

@@ -1,3 +1,5 @@
+// Copyright 2016 Yahoo Inc.
+// Licensed under the terms of the Apache license. Please see LICENSE.md file distributed with this work for terms.
 package com.yahoo.bard.webservice.logging.blocks
 
 import com.yahoo.bard.webservice.data.dimension.Dimension