Adds some additional timings.

CHANGELOG.md

@@ -14,6 +14,7 @@ Current
     * Supported for both Cache v1 and V2
     * Controlled with `bard__druid_max_response_length_to_cache` setting
     * Default value is `MAX_LONG`, so no cache prevention will happen by default
+- [Logs more finegrained timings of the request processing workflow](https://github.com/yahoo/fili/pull/110)
 
 - [Add `FilteredAggregationMaker`](https://github.com/yahoo/fili/pull/107)
     * This version is rudimentary. See [issue 120](https://github.com/yahoo/fili/issue/120) for plans on updating this

fili-core/src/main/java/com/yahoo/bard/webservice/data/dimension/impl/LuceneSearchProvider.java

@@ -8,6 +8,7 @@
 import com.yahoo.bard.webservice.data.dimension.DimensionRow;
 import com.yahoo.bard.webservice.data.dimension.KeyValueStore;
 import com.yahoo.bard.webservice.data.dimension.SearchProvider;
+import com.yahoo.bard.webservice.logging.RequestLog;
 import com.yahoo.bard.webservice.util.DimensionStoreKeyUtils;
 import com.yahoo.bard.webservice.util.Pagination;
 import com.yahoo.bard.webservice.util.SinglePagePagination;
@@ -547,38 +548,55 @@ private Pagination<DimensionRow> getResultsPage(Query query, PaginationParameter
         initializeIndexSearcher();
         lock.readLock().lock();
         try {
-            ScoreDoc[] hits = getPageOfData(luceneIndexSearcher, null, query, perPage, requestedPageNumber).scoreDocs;
-            if (hits.length == 0) {
-                if (requestedPageNumber == 1) {
-                    return new SinglePagePagination<>(Collections.emptyList(), paginationParameters, 0);
-                } else {
-                    throw new PageNotFoundException(requestedPageNumber, perPage, 0);
-                }
-            }
-            for (int currentPage = 1; currentPage < requestedPageNumber; currentPage++) {
-                ScoreDoc lastEntry = hits[hits.length - 1];
-                hits = getPageOfData(luceneIndexSearcher, lastEntry, query, perPage, requestedPageNumber).scoreDocs;
+            RequestLog.startTiming("QueryingLucene");
+            ScoreDoc[] hits;
+            try {
+                hits = getPageOfData(
+                        luceneIndexSearcher,
+                        null,
+                        query,
+                        perPage,
+                        requestedPageNumber
+                ).scoreDocs;
                 if (hits.length == 0) {
-                    throw new PageNotFoundException(requestedPageNumber, perPage, 0);
+                    if (requestedPageNumber == 1) {
+                        return new SinglePagePagination<>(Collections.emptyList(), paginationParameters, 0);
+                    } else {
+                        throw new PageNotFoundException(requestedPageNumber, perPage, 0);
+                    }
                 }
+                for (int currentPage = 1; currentPage < requestedPageNumber; currentPage++) {
+                    ScoreDoc lastEntry = hits[hits.length - 1];
+                    hits = getPageOfData(luceneIndexSearcher, lastEntry, query, perPage, requestedPageNumber).scoreDocs;
+                    if (hits.length == 0) {
+                        throw new PageNotFoundException(requestedPageNumber, perPage, 0);
+                    }
+                }
+            } finally {
+                RequestLog.stopTiming("QueryingLucene");
             }
 
             // convert hits to dimension rows
-            String idKey = DimensionStoreKeyUtils.getColumnKey(dimension.getKey().getName());
-            filteredDimRows = Arrays.stream(hits)
-                    .map(
-                            hit -> {
-                                try {
-                                    return luceneIndexSearcher.doc(hit.doc);
-                                } catch (IOException e) {
-                                    LOG.error("Unable to convert hit " + hit);
-                                    throw new RuntimeException(e);
+            RequestLog.startTiming("LuceneHydratingDimensionRows");
+            try {
+                String idKey = DimensionStoreKeyUtils.getColumnKey(dimension.getKey().getName());
+                filteredDimRows = Arrays.stream(hits)
+                        .map(
+                                hit -> {
+                                    try {
+                                        return luceneIndexSearcher.doc(hit.doc);
+                                    } catch (IOException e) {
+                                        LOG.error("Unable to convert hit " + hit);
+                                        throw new RuntimeException(e);
+                                    }
                                 }
-                            }
-                    )
-                    .map(document -> document.get(idKey))
-                    .map(dimension::findDimensionRowByKeyValue)
-                    .collect(Collectors.toCollection(TreeSet::new));
+                        )
+                        .map(document -> document.get(idKey))
+                        .map(dimension::findDimensionRowByKeyValue)
+                        .collect(Collectors.toCollection(TreeSet::new));
+            } finally {
+                RequestLog.stopTiming("LuceneHydratingDimensionRows");
+            }
 
             documentCount = luceneIndexSearcher.count(query); //throws the caught IOException
         } catch (IOException e) {

fili-core/src/main/java/com/yahoo/bard/webservice/druid/client/impl/AsyncDruidWebServiceImpl.java

@@ -296,45 +296,53 @@ public void postDruidQuery(
             FailureCallback failure,
             DruidQuery<?> druidQuery
     ) {
-        String entityBody;
-        try {
-            entityBody = writer.writeValueAsString(druidQuery);
-        } catch (JsonProcessingException e) {
-            throw new IllegalStateException(e);
-        }
-
         long seqNum = druidQuery.getContext().getSequenceNumber();
-        long totalQueries = druidQuery.getContext().getNumberOfQueries();
-        String format = String.format("%%0%dd", String.valueOf(totalQueries).length());
-        String timerName;
-        AtomicLong outstanding;
-
-        if (!(druidQuery instanceof WeightEvaluationQuery)) {
-            if (context.getNumberOfOutgoing().decrementAndGet() == 0) {
-                RequestLog.stopTiming(REQUEST_WORKFLOW_TIMER);
+        RequestLog.startTiming("PostingDruidQuery" + seqNum);
+        try {
+            String entityBody;
+            RequestLog.startTiming("DruidQuerySerializationSeq" + seqNum);
+            try {
+                entityBody = writer.writeValueAsString(druidQuery);
+            } catch (JsonProcessingException e) {
+                throw new IllegalStateException(e);
+            } finally {
+                RequestLog.stopTiming("DruidQuerySerializationSeq" + seqNum);
             }
-            outstanding = context.getNumberOfIncoming();
-            timerName = DRUID_QUERY_TIMER + String.format(format, seqNum);
-        } else {
-            outstanding = new AtomicLong(0);
-            timerName = DRUID_WEIGHTED_QUERY_TIMER + String.format(format, seqNum);
-        }
-
-        BoundRequestBuilder requestBuilder = webClient.preparePost(serviceConfig.getUrl())
-                .setBody(entityBody)
-                .addHeader("Content-Type", "application/json");
 
-        headersToAppend.get().forEach(requestBuilder::addHeader);
+            long totalQueries = druidQuery.getContext().getNumberOfQueries();
+            String format = String.format("%%0%dd", String.valueOf(totalQueries).length());
+            String timerName;
+            AtomicLong outstanding;
+
+            if (!(druidQuery instanceof WeightEvaluationQuery)) {
+                if (context.getNumberOfOutgoing().decrementAndGet() == 0) {
+                    RequestLog.stopTiming(REQUEST_WORKFLOW_TIMER);
+                }
+                outstanding = context.getNumberOfIncoming();
+                timerName = DRUID_QUERY_TIMER + String.format(format, seqNum);
+            } else {
+                outstanding = new AtomicLong(0);
+                timerName = DRUID_WEIGHTED_QUERY_TIMER + String.format(format, seqNum);
+            }
 
-        LOG.debug("druid json request: {}", entityBody);
-        sendRequest(
-                success,
-                error,
-                failure,
-                requestBuilder,
-                timerName,
-                outstanding
-        );
+            BoundRequestBuilder requestBuilder = webClient.preparePost(serviceConfig.getUrl())
+                    .setBody(entityBody)
+                    .addHeader("Content-Type", "application/json");
+
+            headersToAppend.get().forEach(requestBuilder::addHeader);
+
+            LOG.debug("druid json request: {}", entityBody);
+            sendRequest(
+                    success,
+                    error,
+                    failure,
+                    requestBuilder,
+                    timerName,
+                    outstanding
+            );
+        } finally {
+            RequestLog.stopTiming("PostingDruidQuery" + seqNum);
+        }
     }
 
     @Override

fili-core/src/main/java/com/yahoo/bard/webservice/druid/model/filter/ComplexFilter.java

@@ -0,0 +1,19 @@
+// 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.druid.model.filter;
+
+import java.util.List;
+
+/**
+ * A Druid filter that is defined by applying an operation to at least one other filter. For example, {@code not} and
+ * {@code and} filters are complex. A {@code selector} filter is not.
+ */
+public interface ComplexFilter {
+
+    /**
+     * Returns the filters that are operated on by this filter.
+     *
+     * @return The filters operated on by this filter
+     */
+    List<Filter> getFields();
+}

fili-core/src/main/java/com/yahoo/bard/webservice/druid/model/filter/MultiClauseFilter.java

@@ -9,7 +9,7 @@
 /**
  * Filter parent class for filters which take a list of child filters.
  */
-public abstract class MultiClauseFilter extends Filter {
+public abstract class MultiClauseFilter extends Filter implements ComplexFilter {
 
     private final List<Filter> fields;
 
@@ -24,6 +24,7 @@ protected MultiClauseFilter(FilterType type, List<Filter> fields) {
         this.fields =  Collections.unmodifiableList(fields);
     }
 
+    @Override
     public List<Filter> getFields() {
         return fields;
     }

fili-core/src/main/java/com/yahoo/bard/webservice/druid/model/filter/NotFilter.java

@@ -2,12 +2,16 @@
 // Licensed under the terms of the Apache license. Please see LICENSE.md file distributed with this work for terms.
 package com.yahoo.bard.webservice.druid.model.filter;
 
+import com.fasterxml.jackson.annotation.JsonIgnore;
+
+import java.util.Collections;
+import java.util.List;
 import java.util.Objects;
 
 /**
  * Filter for logical NOT applied to filter expression.
  */
-public class NotFilter extends Filter {
+public class NotFilter extends Filter implements ComplexFilter {
 
     private final Filter field;
 
@@ -49,4 +53,10 @@ public boolean equals(Object obj) {
         return super.equals(obj) &&
                 Objects.equals(field, other.field);
     }
+
+    @Override
+    @JsonIgnore
+    public List<Filter> getFields() {
+        return Collections.singletonList(getField());
+    }
 }

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

@@ -0,0 +1,59 @@
+// 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.druid.model.filter.ComplexFilter;
+import com.yahoo.bard.webservice.druid.model.filter.Filter;
+import com.yahoo.bard.webservice.logging.LogInfo;
+
+import com.fasterxml.jackson.annotation.JsonAutoDetect;
+
+import java.util.ArrayDeque;
+import java.util.Collections;
+import java.util.Deque;
+import java.util.LinkedHashMap;
+import java.util.Map;
+
+/**
+ * Logs some structural data about the filter sent to Druid, without actually logging the entire (potentially massive)
+ * filter.
+ */
+@JsonAutoDetect(fieldVisibility = JsonAutoDetect.Visibility.ANY)
+public class DruidFilterInfo implements LogInfo {
+
+    protected final Map<String, Long> numEachFilterType;
+
+    /**
+     * Constructor.
+     *
+     * @param filter  The filter that needs to be analyzed
+     */
+    public DruidFilterInfo(Filter filter) {
+        numEachFilterType = buildFilterCount(filter);
+    }
+
+    /**
+     * Performs a DFS search of the filter tree, populating the specified map with the number of instances of each
+     * filter type appearing in the filter.
+     *
+     * @param filter  The filter that needs to be traversed
+     *
+     * @return A map containing a count of each type of filter
+     */
+    private Map<String, Long> buildFilterCount(Filter filter) {
+        if (filter == null) {
+            return Collections.emptyMap();
+        }
+        Map<String, Long> filterTypeCounter = new LinkedHashMap<>();
+        Deque<Filter> filterStack = new ArrayDeque<>();
+        filterStack.add(filter);
+        while (!filterStack.isEmpty()) {
+            Filter currentFilter = filterStack.pop();
+            filterTypeCounter.merge(currentFilter.getClass().getSimpleName(), 1L, (old, increment) -> old + increment);
+            if (currentFilter instanceof ComplexFilter) {
+                filterStack.addAll(((ComplexFilter) currentFilter).getFields());
+            }
+        }
+        return filterTypeCounter;
+    }
+}