diff --git a/CHANGELOG.md b/CHANGELOG.md index f4741adc93..e77481954f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -37,9 +37,16 @@ Current * The previous message of `reject ` wasn't helpful, useful, nor very nice to users, and the message logged was not very useful either. The message has been made nicer (`Service is unhealthy. At least 1 healthcheck is failing`), and the log has been made better as well. +- [`RequestLog` timings support the try-with-resources block](https://github.com/yahoo/fili/pull/143) + * A block of code can now be timed by wrapping the timed block in a try-with-resources block that + starts the timer. Note: This won't work when performing timings across threads, or across + contexts. Those need to be started and stopped manually. ### Deprecated: +- [`RequestLog::stopMostRecentTimer` has been deprecated](https://github.com/yahoo/fili/pull/143) + - This method is a part of the infrastructure to support the recently + deprecated `RequestLog::switchTiming`. ### Fixed: 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 index 21370445f3..1f5e767f6e 100644 --- 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 @@ -66,7 +66,7 @@ public void onNext(String jobView) { * @param asyncResponse The channel over which to send the response */ private void send(Response response, AsyncResponse asyncResponse) { - if (RequestLog.isStarted(RESPONSE_WORKFLOW_TIMER)) { + if (RequestLog.isRunning(RESPONSE_WORKFLOW_TIMER)) { RequestLog.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 index 4574fdcfa6..d8477c1796 100644 --- 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 @@ -113,7 +113,7 @@ public void onNext(PreResponse preResponse) { * @param response The Response to send back to the user */ private void publishResponse(Response response) { - if (RequestLog.isStarted(RESPONSE_WORKFLOW_TIMER)) { + if (RequestLog.isRunning(RESPONSE_WORKFLOW_TIMER)) { RequestLog.stopTiming(RESPONSE_WORKFLOW_TIMER); } asyncResponse.resume(response); diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/data/dimension/impl/LuceneSearchProvider.java b/fili-core/src/main/java/com/yahoo/bard/webservice/data/dimension/impl/LuceneSearchProvider.java index 9d7a95640f..5867a8d76a 100644 --- a/fili-core/src/main/java/com/yahoo/bard/webservice/data/dimension/impl/LuceneSearchProvider.java +++ b/fili-core/src/main/java/com/yahoo/bard/webservice/data/dimension/impl/LuceneSearchProvider.java @@ -9,6 +9,7 @@ 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.logging.TimedPhase; import com.yahoo.bard.webservice.util.DimensionStoreKeyUtils; import com.yahoo.bard.webservice.util.Pagination; import com.yahoo.bard.webservice.util.SinglePagePagination; @@ -547,9 +548,8 @@ private Pagination getResultsPage(Query query, PaginationParameter initializeIndexSearcher(); lock.readLock().lock(); try { - RequestLog.startTiming("QueryingLucene"); ScoreDoc[] hits; - try { + try (TimedPhase timer = RequestLog.startTiming("QueryingLucene")) { hits = getPageOfData( luceneIndexSearcher, null, @@ -571,13 +571,10 @@ private Pagination getResultsPage(Query query, PaginationParameter throw new PageNotFoundException(requestedPageNumber, perPage, 0); } } - } finally { - RequestLog.stopTiming("QueryingLucene"); } // convert hits to dimension rows - RequestLog.startTiming("LuceneHydratingDimensionRows"); - try { + try (TimedPhase timer = RequestLog.startTiming("LuceneHydratingDimensionRows")) { String idKey = DimensionStoreKeyUtils.getColumnKey(dimension.getKey().getName()); filteredDimRows = Arrays.stream(hits) .map( @@ -593,8 +590,6 @@ private Pagination getResultsPage(Query query, PaginationParameter .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 diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/logging/RequestLog.java b/fili-core/src/main/java/com/yahoo/bard/webservice/logging/RequestLog.java index cd42f17e85..5123f31850 100644 --- a/fili-core/src/main/java/com/yahoo/bard/webservice/logging/RequestLog.java +++ b/fili-core/src/main/java/com/yahoo/bard/webservice/logging/RequestLog.java @@ -55,6 +55,7 @@ public class RequestLog { private String logId; private LogBlock info; + @Deprecated private TimedPhase mostRecentTimer; private final Map times; private final Set threadIds; @@ -85,54 +86,6 @@ private RequestLog(RequestLog rl) { MDC.put(ID_KEY, logId); } - /** - * Represents a phase that is timed. - * TimedPhase is used to associate a Timer located in the registry with the exact duration of such a phase for a - * specific request. - */ - private static class TimedPhase { - private final String name; - private long start; - private long duration; - - /** - * Constructor. - * - * @param name Name of the phase - */ - private TimedPhase(String name) { - this.name = name; - } - - /** - * Start the phase. - */ - private void start() { - if (start != 0) { - LOG.warn("Tried to start timer that is already running: {}", name); - return; - } - start = System.nanoTime(); - } - - /** - * Stop the phase. - */ - private void stop() { - if (start == 0) { - LOG.warn("Tried to stop timer that has not been started: {}", name); - return; - } - duration += System.nanoTime() - start; - REGISTRY.timer(name).update(duration, TimeUnit.NANOSECONDS); - start = 0; - } - - private boolean isStarted() { - return start != 0; - } - } - /** * Resets the contents of a request log at the calling thread. */ @@ -180,19 +133,7 @@ private void init() { * @return the map containing all the recorded times per phase in milliseconds */ private Map getDurations() { - return times.values() - .stream() - .peek( - phase -> { - if (phase.start != 0) { - LOG.warn( - "Exporting duration while timer is running. Measurement might be wrong: {}", - phase.name - ); - } - } - ) - .collect(Collectors.toMap(phase -> phase.name, phase -> phase.duration)); + return times.values().stream().collect(Collectors.toMap(TimedPhase::getName, TimedPhase::getDuration)); } /** @@ -221,15 +162,15 @@ private Map aggregateDurations() { } /** - * Check if a stopwatch is started. + * Check if a stopwatch is currently running. * * @param caller the caller to name this stopwatch with its class's simple name * * @return whether this stopwatch is started */ - public static boolean isStarted(Object caller) { - return isStarted(caller.getClass().getSimpleName()); + public static boolean isRunning(Object caller) { + return isRunning(caller.getClass().getSimpleName()); } /** @@ -239,10 +180,10 @@ public static boolean isStarted(Object caller) { * * @return whether this stopwatch is started */ - public static boolean isStarted(String timePhaseName) { + public static boolean isRunning(String timePhaseName) { RequestLog current = RLOG.get(); TimedPhase timePhase = current.times.get(timePhaseName); - return timePhase != null && timePhase.isStarted(); + return timePhase != null && timePhase.isRunning(); } /** @@ -250,9 +191,11 @@ public static boolean isStarted(String timePhaseName) { * Time is accumulated if the stopwatch is already registered * * @param caller the caller to name this stopwatch with its class's simple name + * + * @return The stopwatch */ - public static void startTiming(Object caller) { - startTiming(caller.getClass().getSimpleName()); + public static TimedPhase startTiming(Object caller) { + return startTiming(caller.getClass().getSimpleName()); } /** @@ -260,8 +203,10 @@ public static void startTiming(Object caller) { * Time is accumulated if the stopwatch is already registered * * @param timePhaseName the name of this stopwatch + * + * @return The stopwatch */ - public static void startTiming(String timePhaseName) { + public static TimedPhase startTiming(String timePhaseName) { RequestLog current = RLOG.get(); TimedPhase timePhase = current.times.get(timePhaseName); if (timePhase == null) { @@ -274,7 +219,7 @@ public static void startTiming(String timePhaseName) { current.times.put(timePhaseName, timePhase); } current.mostRecentTimer = timePhase; - timePhase.start(); + return timePhase.start(); } /** @@ -302,6 +247,15 @@ public static void stopTiming(Object caller) { stopTiming(caller.getClass().getSimpleName()); } + /** + * Registers the final duration of a stopped timer with the RequestLog. + * + * @param stoppedPhase The phase that has been stopped, and whose duration needs to be stored + */ + public static void registerTime(TimedPhase stoppedPhase) { + RequestLog.REGISTRY.timer(stoppedPhase.getName()).update(stoppedPhase.getDuration(), stoppedPhase.getUnit()); + } + /** * Pause a stopwatch. * @@ -313,15 +267,19 @@ public static void stopTiming(String timePhaseName) { LOG.warn("Tried to stop non-existent phase: {}", timePhaseName); return; } - timePhase.stop(); + timePhase.close(); } /** * Stop the most recent stopwatch. + * + * @deprecated Stopping a timer based on context is brittle, and prone to unexpected changes. Timers should be + * stopped explicitly, or started in a try-with-resources block */ + @Deprecated public static void stopMostRecentTimer() { try { - stopTiming(RLOG.get().mostRecentTimer.name); + stopTiming(RLOG.get().mostRecentTimer.getName()); } catch (NullPointerException ignored) { LOG.warn("Stopping timing failed because mostRecentTimer wasn't registered."); } @@ -450,8 +408,8 @@ public static void accumulate(RequestLog ctx) { .stream() .filter( e -> e.getKey().contains(DRUID_QUERY_TIMER) || - (e.getKey().equals(REQUEST_WORKFLOW_TIMER) && !e.getValue().isStarted()) || - (e.getKey().equals(RESPONSE_WORKFLOW_TIMER) && e.getValue().isStarted()) + (e.getKey().equals(REQUEST_WORKFLOW_TIMER) && !e.getValue().isRunning()) || + (e.getKey().equals(RESPONSE_WORKFLOW_TIMER) && e.getValue().isRunning()) ) .collect(Collectors.toMap(Map.Entry::getKey, Map.Entry::getValue)) ); diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/logging/TimedPhase.java b/fili-core/src/main/java/com/yahoo/bard/webservice/logging/TimedPhase.java new file mode 100644 index 0000000000..8534ca4009 --- /dev/null +++ b/fili-core/src/main/java/com/yahoo/bard/webservice/logging/TimedPhase.java @@ -0,0 +1,119 @@ +// 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; + +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +import java.util.concurrent.TimeUnit; + +/** + * Represents a phase that is timed. + * TimedPhase is used to associate a Timer located in the registry with the exact duration of such a phase for a + * specific request. Times are in nanoseconds. + *

+ * Note: This class is NOT thread-safe. Timers are intended to be started once by one thread, and stopped once by + * one thread (though those threads are not necessarily the same). + */ +public class TimedPhase implements AutoCloseable { + private static final Logger LOG = LoggerFactory.getLogger(TimedPhase.class); + + private final String name; + private long start; + private long duration; + + /** + * Constructor. + * + * @param name Name of the phase + */ + public TimedPhase(String name) { + this.name = name; + } + + /** + * Start the phase. + * + * @return This phase after being started + */ + public TimedPhase start() { + if (isRunning()) { + LOG.warn("Tried to start timer that is already running: {}", name); + } else { + start = System.nanoTime(); + } + return this; + } + + /** + * Stop the phase. + *

+ * This method just stops the timer. It does not register the time with the {@link RequestLog}. To register + * the timer, invoke {@link TimedPhase#registerTime()}. To do both with a single method call, see + * {@link TimedPhase#close()} + * + * @see TimedPhase#registerTime() + * @see TimedPhase#close() + */ + public void stop() { + if (!isRunning()) { + LOG.warn("Tried to stop timer that has not been started: {}", name); + return; + } + duration += System.nanoTime() - start; + start = 0; + } + + /** + * Registers the duration of this timer with the RequestLog. + *

+ * It is highly recommended that you {@link TimedPhase#stop()}} the timer first. Otherwise, the timings may + * be inaccurate. To both stop and register the timer at once see {@link TimedPhase#close}. + * + * @see TimedPhase#stop() + * @see TimedPhase#close() + */ + public void registerTime() { + RequestLog.registerTime(this); + } + + /** + * Return the duration of the timer in nanoseconds. + * + * @return The duration of the timer in nanoseconds + */ + public long getDuration() { + if (isRunning()) { + LOG.warn("Timer '{}' is still running. Timings may be incorrect.", getName()); + } + return duration; + } + + public String getName() { + return name; + } + + public TimeUnit getUnit() { + return TimeUnit.NANOSECONDS; + } + + public boolean isRunning() { + return start != 0; + } + + /** + * Stops the timer, and registers the timer with the RequestLog. + *

+ * This is primarily meant to be used by the try-with-resources block, which both stops the timer and registers it + * with the RequestLog, though it can of course be called manually as well. If you want to stop the timer, but + * don't want to register the timer just yet, then see {@link TimedPhase#stop}. + * + * @see TimedPhase#stop() + * @see TimedPhase#registerTime() + */ + @Override + public void close() { + stop(); + registerTime(); + } +} diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/web/DataApiRequest.java b/fili-core/src/main/java/com/yahoo/bard/webservice/web/DataApiRequest.java index 7dcf2c50fb..4f7739ce18 100644 --- a/fili-core/src/main/java/com/yahoo/bard/webservice/web/DataApiRequest.java +++ b/fili-core/src/main/java/com/yahoo/bard/webservice/web/DataApiRequest.java @@ -49,6 +49,7 @@ import com.yahoo.bard.webservice.druid.model.query.Granularity; import com.yahoo.bard.webservice.druid.util.FieldConverterSupplier; import com.yahoo.bard.webservice.logging.RequestLog; +import com.yahoo.bard.webservice.logging.TimedPhase; import com.yahoo.bard.webservice.table.LogicalTable; import com.yahoo.bard.webservice.table.TableIdentifier; import com.yahoo.bard.webservice.util.StreamUtils; @@ -227,14 +228,11 @@ public DataApiRequest( this.filters = generateFilters(filters, table, dimensionDictionary); validateRequestDimensions(this.filters.keySet(), this.table); - RequestLog.startTiming("BuildingDruidFilter"); - try { + try (TimedPhase timer = RequestLog.startTiming("BuildingDruidFilter")) { this.filter = filterBuilder.buildFilters(this.filters); } catch (DimensionRowNotFoundException e) { LOG.debug(e.getMessage()); throw new BadApiRequestException(e); - } finally { - RequestLog.stopTiming("BuildingDruidFilter"); } // Zero or more having queries may be referenced @@ -389,8 +387,7 @@ protected LinkedHashMap generateSortColumns(String sorts) * @return the request's TimeZone */ private DateTimeZone generateTimeZone(String timeZoneId, DateTimeZone systemTimeZone) { - RequestLog.startTiming("generatingTimeZone"); - try { + try (TimedPhase timer = RequestLog.startTiming("generatingTimeZone")) { if (timeZoneId == null) { return systemTimeZone; } @@ -400,8 +397,6 @@ private DateTimeZone generateTimeZone(String timeZoneId, DateTimeZone systemTime LOG.debug(INVALID_TIME_ZONE.logFormat(timeZoneId)); throw new BadApiRequestException(INVALID_TIME_ZONE.format(timeZoneId)); } - } finally { - RequestLog.stopTiming("generatingTimeZone"); } } @@ -569,8 +564,7 @@ protected LinkedHashSet generateDimensions( List apiDimensions, DimensionDictionary dimensionDictionary ) throws BadApiRequestException { - RequestLog.startTiming("GeneratingDimensions"); - try { + try (TimedPhase timer = RequestLog.startTiming("GeneratingDimensions")) { // Dimensions are optional hence check if dimensions are requested. if (apiDimensions == null || apiDimensions.isEmpty()) { return new LinkedHashSet<>(); @@ -603,8 +597,6 @@ protected LinkedHashSet generateDimensions( LOG.trace("Generated set of dimension: {}", generated); return generated; - } finally { - RequestLog.stopTiming("GeneratingDimensions"); } } @@ -623,8 +615,7 @@ protected LinkedHashMap> generateDimens @NotNull List apiDimensionPathSegments, @NotNull DimensionDictionary dimensionDictionary ) { - RequestLog.startTiming("GeneratingDimensionFields"); - try { + try (TimedPhase timer = RequestLog.startTiming("GeneratingDimensionFields")) { return apiDimensionPathSegments.stream() .filter(pathSegment -> !pathSegment.getPath().isEmpty()) .collect(Collectors.toMap( @@ -636,8 +627,6 @@ protected LinkedHashMap> generateDimens }, LinkedHashMap::new )); - } finally { - RequestLog.stopTiming("GeneratingDimensionFields"); } } @@ -809,8 +798,7 @@ protected LinkedHashSet generateLogicalMetrics( DimensionDictionary dimensionDictionary, LogicalTable table ) throws BadApiRequestException { - RequestLog.startTiming("GeneratingLogicalMetrics"); - try { + try (TimedPhase timer = RequestLog.startTiming("GeneratingLogicalMetrics")) { LOG.trace("Metric dictionary: {}", metricDictionary); if (apiMetricQuery == null || "".equals(apiMetricQuery)) { @@ -921,8 +909,6 @@ protected LinkedHashSet generateLogicalMetrics( } LOG.trace("Generated set of logical metric: {}", generated); return generated; - } finally { - RequestLog.stopTiming("GeneratingLogicalMetrics"); } } @@ -983,8 +969,7 @@ protected static Set generateIntervals( Granularity granularity, DateTimeFormatter dateTimeFormatter ) throws BadApiRequestException { - RequestLog.startTiming("GeneratingIntervals"); - try { + try (TimedPhase timer = RequestLog.startTiming("GeneratingIntervals")) { Set generated = new LinkedHashSet<>(); if (apiIntervalQuery == null || apiIntervalQuery.equals("")) { LOG.debug(INTERVAL_MISSING.logFormat()); @@ -1054,8 +1039,6 @@ protected static Set generateIntervals( } } return generated; - } finally { - RequestLog.stopTiming("GeneratingIntervals"); } } @@ -1077,8 +1060,7 @@ protected Map> generateFilters( LogicalTable table, DimensionDictionary dimensionDictionary ) throws BadApiRequestException { - RequestLog.startTiming("GeneratingFilters"); - try { + try (TimedPhase timer = RequestLog.startTiming("GeneratingFilters")) { LOG.trace("Dimension Dictionary: {}", dimensionDictionary); // Set of filter objects Map> generated = new LinkedHashMap<>(); @@ -1119,8 +1101,6 @@ protected Map> generateFilters( LOG.trace("Generated map of filters: {}", generated); return generated; - } finally { - RequestLog.stopTiming("GeneratingFilters"); } } @@ -1141,8 +1121,7 @@ protected Map> generateHavings( Set logicalMetrics, MetricDictionary metricDictionary ) throws BadApiRequestException { - RequestLog.startTiming("GeneratingHavings"); - try { + try (TimedPhase phase = RequestLog.startTiming("GeneratingHavings")) { LOG.trace("Metric Dictionary: {}", metricDictionary); // Havings are optional hence check if havings are requested. if (havingQuery == null || "".equals(havingQuery)) { @@ -1180,8 +1159,6 @@ protected Map> generateHavings( LOG.trace("Generated map of havings: {}", generated); return generated; - } finally { - RequestLog.stopTiming("GeneratingHavings"); } } @@ -1219,8 +1196,7 @@ protected LinkedHashSet generateSortColumns( Set logicalMetrics, MetricDictionary metricDictionary ) throws BadApiRequestException { - RequestLog.startTiming("GeneratingSortColumns"); - try { + try (TimedPhase timer = RequestLog.startTiming("GeneratingSortColumns")) { String sortMetricName; LinkedHashSet metricSortColumns = new LinkedHashSet<>(); @@ -1265,8 +1241,6 @@ protected LinkedHashSet generateSortColumns( } return metricSortColumns; - } finally { - RequestLog.stopTiming("GeneratingSortColumns"); } } diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/web/endpoints/DataServlet.java b/fili-core/src/main/java/com/yahoo/bard/webservice/web/endpoints/DataServlet.java index 871ddf4d2f..9c6e2d216d 100644 --- a/fili-core/src/main/java/com/yahoo/bard/webservice/web/endpoints/DataServlet.java +++ b/fili-core/src/main/java/com/yahoo/bard/webservice/web/endpoints/DataServlet.java @@ -31,6 +31,7 @@ import com.yahoo.bard.webservice.druid.model.query.DruidAggregationQuery; import com.yahoo.bard.webservice.druid.model.query.DruidQuery; import com.yahoo.bard.webservice.logging.RequestLog; +import com.yahoo.bard.webservice.logging.TimedPhase; import com.yahoo.bard.webservice.logging.blocks.BardQueryInfo; import com.yahoo.bard.webservice.logging.blocks.DataRequest; import com.yahoo.bard.webservice.logging.blocks.DruidFilterInfo; @@ -345,9 +346,8 @@ public void getData( @Suspended final AsyncResponse asyncResponse ) { try { - RequestLog.startTiming("DataApiRequest"); DataApiRequest apiRequest; - try { + try (TimedPhase timer = RequestLog.startTiming("DataApiRequest")) { apiRequest = new DataApiRequest( tableName, timeGrain, @@ -367,8 +367,6 @@ public void getData( uriInfo, this ); - } finally { - RequestLog.stopTiming("DataApiRequest"); } if (requestMapper != null) { @@ -376,30 +374,21 @@ public void getData( } // Build the query template - RequestLog.startTiming("DruidQueryMerge"); TemplateDruidQuery templateQuery; - try { + try (TimedPhase timer = RequestLog.startTiming("DruidQueryMerge")) { templateQuery = templateDruidQueryMerger.merge(apiRequest); - } finally { - RequestLog.stopTiming("DruidQueryMerge"); } // Select the performance slice and build the final query DruidAggregationQuery druidQuery; - RequestLog.startTiming("DruidQueryBuilder"); - try { + try (TimedPhase timer = RequestLog.startTiming("DruidQueryBuilder")) { druidQuery = druidQueryBuilder.buildQuery(apiRequest, templateQuery); - } finally { - RequestLog.stopTiming("DruidQueryBuilder"); } // Accumulate data needed for request processing workflow - RequestLog.startTiming("BuildRequestContext"); RequestContext context; - try { + try (TimedPhase timer = RequestLog.startTiming("BuildRequestContext")) { context = new RequestContext(containerRequestContext, readCache); - } finally { - RequestLog.stopTiming("BuildRequestContext"); } //An instance to prepare the Response with different set of arguments @@ -428,12 +417,9 @@ public void getData( httpResponseMaker ); - RequestLog.startTiming("logRequestMetrics"); - try { + try (TimedPhase timer = RequestLog.startTiming("logRequestMetrics")) { logRequestMetrics(apiRequest, readCache, druidQuery); RequestLog.record(new DruidFilterInfo(apiRequest.getFilter())); - } finally { - RequestLog.stopTiming("logRequestMetrics"); } // Process the request diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/web/filters/BardLoggingFilter.java b/fili-core/src/main/java/com/yahoo/bard/webservice/web/filters/BardLoggingFilter.java index ef5aab847e..f4c68dbda5 100644 --- a/fili-core/src/main/java/com/yahoo/bard/webservice/web/filters/BardLoggingFilter.java +++ b/fili-core/src/main/java/com/yahoo/bard/webservice/web/filters/BardLoggingFilter.java @@ -5,6 +5,7 @@ import static javax.ws.rs.core.Response.Status.Family.SUCCESSFUL; import com.yahoo.bard.webservice.logging.RequestLog; +import com.yahoo.bard.webservice.logging.TimedPhase; import com.yahoo.bard.webservice.logging.blocks.Epilogue; import com.yahoo.bard.webservice.logging.blocks.Preface; import com.yahoo.bard.webservice.util.CacheLastObserver; @@ -88,15 +89,15 @@ public void filter(ContainerRequestContext request) throws IOException { appendRequestId(request.getHeaders().getFirst(X_REQUEST_ID_HEADER)); RequestLog.startTiming(TOTAL_TIMER); - RequestLog.startTiming(this); - RequestLog.record(new Preface(request)); + try (TimedPhase timer = RequestLog.startTiming(this)) { + RequestLog.record(new Preface(request)); - // sets PROPERTY_REQ_LEN if content-length not defined - lengthOfRequestEntity(request); + // sets PROPERTY_REQ_LEN if content-length not defined + lengthOfRequestEntity(request); - // store start time to later calculate elapsed time - request.setProperty(PROPERTY_NANOS, System.nanoTime()); - RequestLog.stopTiming(this); + // store start time to later calculate elapsed time + request.setProperty(PROPERTY_NANOS, System.nanoTime()); + } } /** diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/web/responseprocessors/WeightCheckResponseProcessor.java b/fili-core/src/main/java/com/yahoo/bard/webservice/web/responseprocessors/WeightCheckResponseProcessor.java index ef356808f7..10a22a21e8 100644 --- a/fili-core/src/main/java/com/yahoo/bard/webservice/web/responseprocessors/WeightCheckResponseProcessor.java +++ b/fili-core/src/main/java/com/yahoo/bard/webservice/web/responseprocessors/WeightCheckResponseProcessor.java @@ -38,7 +38,7 @@ public FailureCallback getFailureCallback(final DruidAggregationQuery druidQu return new FailureCallback() { @Override public void invoke(Throwable error) { - if (RequestLog.isStarted(REQUEST_WORKFLOW_TIMER)) { + if (RequestLog.isRunning(REQUEST_WORKFLOW_TIMER)) { RequestLog.stopTiming(REQUEST_WORKFLOW_TIMER); } next.getFailureCallback(druidQuery).invoke(error); @@ -51,7 +51,7 @@ public HttpErrorCallback getErrorCallback(final DruidAggregationQuery druidQu return new HttpErrorCallback() { @Override public void invoke(int statusCode, String reason, String responseBody) { - if (RequestLog.isStarted(REQUEST_WORKFLOW_TIMER)) { + if (RequestLog.isRunning(REQUEST_WORKFLOW_TIMER)) { RequestLog.stopTiming(REQUEST_WORKFLOW_TIMER); } next.getErrorCallback(druidQuery).invoke(statusCode, reason, responseBody); diff --git a/fili-core/src/test/groovy/com/yahoo/bard/webservice/web/responseprocessors/WeightCheckResponseProcessorSpec.groovy b/fili-core/src/test/groovy/com/yahoo/bard/webservice/web/responseprocessors/WeightCheckResponseProcessorSpec.groovy index 3275a96895..7001335b33 100644 --- a/fili-core/src/test/groovy/com/yahoo/bard/webservice/web/responseprocessors/WeightCheckResponseProcessorSpec.groovy +++ b/fili-core/src/test/groovy/com/yahoo/bard/webservice/web/responseprocessors/WeightCheckResponseProcessorSpec.groovy @@ -44,7 +44,7 @@ class WeightCheckResponseProcessorSpec extends Specification{ then: "no timer is stopped and proccessing continues to the next processor" // This check is artifial. Is meant to check that there is no call to stopTiming() for this timer in the // regular execution path of the WeightCheckResponseProcessor - RequestLog.isStarted(REQUEST_WORKFLOW_TIMER) == true + RequestLog.isRunning(REQUEST_WORKFLOW_TIMER) == true 1 * next.processResponse(json, groupByQuery, null) } @@ -57,7 +57,7 @@ class WeightCheckResponseProcessorSpec extends Specification{ wcrp.getFailureCallback(groupByQuery).invoke(t) then: "The REQUEST_WORKFLOW_TIMER is stopped" - RequestLog.isStarted(REQUEST_WORKFLOW_TIMER) == false + RequestLog.isRunning(REQUEST_WORKFLOW_TIMER) == false then: "and the failure callback of the next processor is called" 1 * next.getFailureCallback(groupByQuery) >> nextFail @@ -77,7 +77,7 @@ class WeightCheckResponseProcessorSpec extends Specification{ wcrp.getErrorCallback(groupByQuery).invoke(statusCode, reason, body) then: "The REQUEST_WORKFLOW_TIMER is stopped" - RequestLog.isStarted(REQUEST_WORKFLOW_TIMER) == false + RequestLog.isRunning(REQUEST_WORKFLOW_TIMER) == false then: "and the http error callback of the next processor is called" 1 * next.getErrorCallback(groupByQuery) >> nextError