yahoo · michael-mclawhorn · Nov 17, 2016
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -99,6 +99,12 @@ Current
         starts the timer. Note: This won't work when performing timings across threads, or across
         contexts. Those need to be started and stopped manually.
 
+- [Expose the request phase durations stored by RequestLog](https://github.com/yahoo/fili/pull/100)
+    * Refactored the RequestLog by spinning the model out into a seperate class and marking the existing class as a
+    utility
+
+### Changed:
+
 ### Deprecated:
 
 - [`RequestLog::stopMostRecentTimer` has been deprecated](https://github.com/yahoo/fili/pull/143)

diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/async/MetadataHttpResponseChannel.java b/fili-core/src/main/java/com/yahoo/bard/webservice/async/MetadataHttpResponseChannel.java
@@ -4,7 +4,7 @@
 
 import static com.yahoo.bard.webservice.web.handlers.workflow.DruidWorkflow.RESPONSE_WORKFLOW_TIMER;
 
-import com.yahoo.bard.webservice.logging.RequestLog;
+import com.yahoo.bard.webservice.logging.RequestLogUtils;
 import com.yahoo.bard.webservice.web.ErrorMessageFormat;
 import com.yahoo.bard.webservice.web.handlers.RequestHandlerUtils;
 
@@ -66,8 +66,8 @@ public void onNext(String jobView) {
      * @param asyncResponse  The channel over which to send the response
      */
     private void send(Response response, AsyncResponse asyncResponse) {
-        if (RequestLog.isRunning(RESPONSE_WORKFLOW_TIMER)) {
-            RequestLog.stopTiming(RESPONSE_WORKFLOW_TIMER);
+        if (RequestLogUtils.isRunning(RESPONSE_WORKFLOW_TIMER)) {
+            RequestLogUtils.stopTiming(RESPONSE_WORKFLOW_TIMER);
         }
         asyncResponse.resume(response);
     }

diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/data/HttpResponseChannel.java b/fili-core/src/main/java/com/yahoo/bard/webservice/data/HttpResponseChannel.java
@@ -5,7 +5,7 @@
 import static com.yahoo.bard.webservice.web.handlers.workflow.DruidWorkflow.RESPONSE_WORKFLOW_TIMER;
 
 import com.yahoo.bard.webservice.async.ResponseException;
-import com.yahoo.bard.webservice.logging.RequestLog;
+import com.yahoo.bard.webservice.logging.RequestLogUtils;
 import com.yahoo.bard.webservice.web.DataApiRequest;
 import com.yahoo.bard.webservice.web.PreResponse;
 import com.yahoo.bard.webservice.web.ResponseFormatType;
@@ -113,8 +113,8 @@ public void onNext(PreResponse preResponse) {
      * @param response  The Response to send back to the user
      */
     private void publishResponse(Response response) {
-        if (RequestLog.isRunning(RESPONSE_WORKFLOW_TIMER)) {
-            RequestLog.stopTiming(RESPONSE_WORKFLOW_TIMER);
+        if (RequestLogUtils.isRunning(RESPONSE_WORKFLOW_TIMER)) {
+            RequestLogUtils.stopTiming(RESPONSE_WORKFLOW_TIMER);
         }
         asyncResponse.resume(response);
     }

diff --git a/...ore/src/main/java/com/yahoo/bard/webservice/data/dimension/impl/LuceneSearchProvider.java b/...ore/src/main/java/com/yahoo/bard/webservice/data/dimension/impl/LuceneSearchProvider.java
@@ -11,8 +11,8 @@
 import com.yahoo.bard.webservice.data.dimension.KeyValueStore;
 import com.yahoo.bard.webservice.data.dimension.SearchProvider;
 import com.yahoo.bard.webservice.data.dimension.TimeoutException;
-import com.yahoo.bard.webservice.logging.RequestLog;
 import com.yahoo.bard.webservice.logging.TimedPhase;
+import com.yahoo.bard.webservice.logging.RequestLogUtils;
 import com.yahoo.bard.webservice.util.DimensionStoreKeyUtils;
 import com.yahoo.bard.webservice.util.Pagination;
 import com.yahoo.bard.webservice.util.SinglePagePagination;
@@ -573,7 +573,7 @@ private Pagination<DimensionRow> getResultsPage(Query query, PaginationParameter
         lock.readLock().lock();
         try {
             ScoreDoc[] hits;
-            try (TimedPhase timer = RequestLog.startTiming("QueryingLucene")) {
+            try (TimedPhase timer = RequestLogUtils.startTiming("QueryingLucene")) {
                 hits = getPageOfData(
                         luceneIndexSearcher,
                         null,
@@ -598,7 +598,7 @@ private Pagination<DimensionRow> getResultsPage(Query query, PaginationParameter
             }
 
             // convert hits to dimension rows
-            try (TimedPhase timer = RequestLog.startTiming("LuceneHydratingDimensionRows")) {
+            try (TimedPhase timer = RequestLogUtils.startTiming("LuceneHydratingDimensionRows")) {
                 String idKey = DimensionStoreKeyUtils.getColumnKey(dimension.getKey().getName());
                 filteredDimRows = Arrays.stream(hits)
                         .map(
@@ -615,7 +615,6 @@ private Pagination<DimensionRow> getResultsPage(Query query, PaginationParameter
                         .map(dimension::findDimensionRowByKeyValue)
                         .collect(Collectors.toCollection(TreeSet::new));
             }
-
             documentCount = luceneIndexSearcher.count(query); //throws the caught IOException
         } catch (IOException e) {
             LOG.error("Unable to get count of matched rows for the query " + query.toString() +

diff --git a/...-core/src/main/java/com/yahoo/bard/webservice/data/metric/mappers/DateTimeSortMapper.java b/...-core/src/main/java/com/yahoo/bard/webservice/data/metric/mappers/DateTimeSortMapper.java
@@ -6,7 +6,7 @@
 import com.yahoo.bard.webservice.data.ResultSet;
 import com.yahoo.bard.webservice.data.ResultSetSchema;
 import com.yahoo.bard.webservice.druid.model.orderby.SortDirection;
-import com.yahoo.bard.webservice.logging.RequestLog;
+import com.yahoo.bard.webservice.logging.TimedPhase;
 
 import org.joda.time.DateTime;
 
@@ -46,8 +46,7 @@ public ResultSet map(ResultSet resultSet) {
 
         Map<DateTime, List<Result>> bucketizedResultsMap = new LinkedHashMap<>();
 
-        RequestLog.startTiming("sortResultSet");
-        try {
+        try (TimedPhase timer = new TimedPhase("sortResultSet")) {
             for (Result result : resultSet) {
                 bucketizedResultsMap.computeIfAbsent(result.getTimeStamp(), ignored -> new ArrayList<>()).add(result);
             }
@@ -65,8 +64,6 @@ public ResultSet map(ResultSet resultSet) {
                             .flatMap(List::stream)
                             .collect(Collectors.toList())
             );
-        } finally {
-            RequestLog.stopTiming("sortResultSet");
         }
     }
 

diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/druid/client/FailureCallback.java b/fili-core/src/main/java/com/yahoo/bard/webservice/druid/client/FailureCallback.java
@@ -5,7 +5,7 @@
 import static com.yahoo.bard.webservice.web.handlers.workflow.DruidWorkflow.REQUEST_WORKFLOW_TIMER;
 import static com.yahoo.bard.webservice.web.handlers.workflow.DruidWorkflow.RESPONSE_WORKFLOW_TIMER;
 
-import com.yahoo.bard.webservice.logging.RequestLog;
+import com.yahoo.bard.webservice.logging.RequestLogUtils;
 
 /**
  * Callback from the async HTTP client on error.
@@ -24,8 +24,8 @@ public interface FailureCallback {
      * @param error  The error that caused the failure
      */
     default void dispatch(Throwable error) {
-        RequestLog.stopTiming(REQUEST_WORKFLOW_TIMER);
-        RequestLog.startTiming(RESPONSE_WORKFLOW_TIMER);
+        RequestLogUtils.stopTiming(REQUEST_WORKFLOW_TIMER);
+        RequestLogUtils.startTiming(RESPONSE_WORKFLOW_TIMER);
         invoke(error);
     }
 }
diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/druid/client/HttpErrorCallback.java b/fili-core/src/main/java/com/yahoo/bard/webservice/druid/client/HttpErrorCallback.java
@@ -5,7 +5,7 @@
 import static com.yahoo.bard.webservice.web.handlers.workflow.DruidWorkflow.REQUEST_WORKFLOW_TIMER;
 import static com.yahoo.bard.webservice.web.handlers.workflow.DruidWorkflow.RESPONSE_WORKFLOW_TIMER;
 
-import com.yahoo.bard.webservice.logging.RequestLog;
+import com.yahoo.bard.webservice.logging.RequestLogUtils;
 
 /**
  * Callback from the async HTTP client on error.
@@ -28,8 +28,8 @@ public interface HttpErrorCallback {
      * @param statusCode  Http status code of the error response
      */
     default void dispatch(int statusCode, String reasonPhrase, String responseBody) {
-        RequestLog.stopTiming(REQUEST_WORKFLOW_TIMER);
-        RequestLog.startTiming(RESPONSE_WORKFLOW_TIMER);
+        RequestLogUtils.stopTiming(REQUEST_WORKFLOW_TIMER);
+        RequestLogUtils.startTiming(RESPONSE_WORKFLOW_TIMER);
         invoke(statusCode, reasonPhrase, responseBody);
     }
 }
diff --git a/...e/src/main/java/com/yahoo/bard/webservice/druid/client/impl/AsyncDruidWebServiceImpl.java b/...e/src/main/java/com/yahoo/bard/webservice/druid/client/impl/AsyncDruidWebServiceImpl.java
@@ -15,6 +15,7 @@
 import com.yahoo.bard.webservice.druid.model.query.DruidQuery;
 import com.yahoo.bard.webservice.druid.model.query.WeightEvaluationQuery;
 import com.yahoo.bard.webservice.logging.RequestLog;
+import com.yahoo.bard.webservice.logging.RequestLogUtils;
 import com.yahoo.bard.webservice.logging.blocks.DruidResponse;
 import com.yahoo.bard.webservice.web.handlers.RequestContext;
 
@@ -186,21 +187,21 @@ protected void sendRequest(
             final String timerName,
             final AtomicLong outstanding
     ) {
-        RequestLog.startTiming(timerName);
-        final RequestLog logCtx = RequestLog.dump();
+        RequestLogUtils.startTiming(timerName);
+        final RequestLog logCtx = RequestLogUtils.dump();
 
         try {
             requestBuilder.execute(
                 new AsyncCompletionHandler<Response>() {
                     @Override
                     public Response onCompleted(Response response) {
-                        RequestLog.restore(logCtx);
-                        RequestLog.stopTiming(timerName);
+                        RequestLogUtils.restore(logCtx);
+                        RequestLogUtils.stopTiming(timerName);
                         if (outstanding.decrementAndGet() == 0) {
-                            RequestLog.startTiming(RESPONSE_WORKFLOW_TIMER);
+                            RequestLogUtils.startTiming(RESPONSE_WORKFLOW_TIMER);
                         }
                         String druidQueryId = response.getHeader("X-Druid-Query-Id");
-                        RequestLog.record(new DruidResponse(druidQueryId));
+                        RequestLogUtils.record(new DruidResponse(druidQueryId));
                         Status status = Status.fromStatusCode(response.getStatusCode());
                         LOG.debug(
                                 "druid {} response code: {} {} and druid query id: {}",
@@ -246,21 +247,21 @@ public Response onCompleted(Response response) {
 
                     @Override
                     public void onThrowable(Throwable t) {
-                        RequestLog.restore(logCtx);
-                        RequestLog.stopTiming(timerName);
+                        RequestLogUtils.restore(logCtx);
+                        RequestLogUtils.stopTiming(timerName);
                         if (outstanding.decrementAndGet() == 0) {
-                            RequestLog.startTiming(RESPONSE_WORKFLOW_TIMER);
+                            RequestLogUtils.startTiming(RESPONSE_WORKFLOW_TIMER);
                         }
                         exceptionMeter.mark();
                         LOG.error("druid {} request failed:", serviceConfig.getNameAndUrl(), t);
                         failure.invoke(t);
                     }
                 });
         } catch (RuntimeException t) {
-            RequestLog.restore(logCtx);
-            RequestLog.stopTiming(timerName);
+            RequestLogUtils.restore(logCtx);
+            RequestLogUtils.stopTiming(timerName);
             if (outstanding.decrementAndGet() == 0) {
-                RequestLog.startTiming(RESPONSE_WORKFLOW_TIMER);
+                RequestLogUtils.startTiming(RESPONSE_WORKFLOW_TIMER);
             }
             LOG.error("druid {} http request failed: ", serviceConfig.getNameAndUrl(), t);
             failure.invoke(t);
@@ -299,13 +300,13 @@ public void postDruidQuery(
     ) {
         long seqNum = druidQuery.getContext().getSequenceNumber();
         String entityBody;
-        RequestLog.startTiming("DruidQuerySerializationSeq" + seqNum);
+        RequestLogUtils.startTiming("DruidQuerySerializationSeq" + seqNum);
         try {
             entityBody = writer.writeValueAsString(druidQuery);
         } catch (JsonProcessingException e) {
             throw new IllegalStateException(e);
         } finally {
-            RequestLog.stopTiming("DruidQuerySerializationSeq" + seqNum);
+            RequestLogUtils.stopTiming("DruidQuerySerializationSeq" + seqNum);
         }
 
         long totalQueries = druidQuery.getContext().getNumberOfQueries();
@@ -315,7 +316,7 @@ public void postDruidQuery(
 
         if (!(druidQuery instanceof WeightEvaluationQuery)) {
             if (context.getNumberOfOutgoing().decrementAndGet() == 0) {
-                RequestLog.stopTiming(REQUEST_WORKFLOW_TIMER);
+                RequestLogUtils.stopTiming(REQUEST_WORKFLOW_TIMER);
             }
             outstanding = context.getNumberOfIncoming();
             timerName = DRUID_QUERY_TIMER + String.format(format, seqNum);

diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/druid/model/query/AbstractDruidQuery.java b/fili-core/src/main/java/com/yahoo/bard/webservice/druid/model/query/AbstractDruidQuery.java
@@ -4,7 +4,7 @@
 
 import com.yahoo.bard.webservice.druid.model.QueryType;
 import com.yahoo.bard.webservice.druid.model.datasource.DataSource;
-import com.yahoo.bard.webservice.logging.RequestLog;
+import com.yahoo.bard.webservice.logging.RequestLogUtils;
 
 import com.fasterxml.jackson.annotation.JsonInclude;
 
@@ -43,7 +43,7 @@ protected AbstractDruidQuery(
         this.dataSource = dataSource;
         this.context = context == null ?
                 new QueryContext(Collections.<QueryContext.Param, Object>emptyMap(), null)
-                        .withQueryId(RequestLog.getId()) :
+                        .withQueryId(RequestLogUtils.getId()) :
                 doFork ? context.fork() : context;
     }
 

diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/logging/JsonLogFormatter.java b/fili-core/src/main/java/com/yahoo/bard/webservice/logging/JsonLogFormatter.java
@@ -16,7 +16,7 @@
  * A log formatter that prints log in JSON format.
  */
 public class JsonLogFormatter implements LogFormatter {
-    private static final Logger LOG = LoggerFactory.getLogger(RequestLog.class);
+    private static final Logger LOG = LoggerFactory.getLogger(RequestLogUtils.class);
     private final ObjectMapper objectMapper;
 
     /**