From d914937fadd273b48d525b007d29b756ee6bfbd7 Mon Sep 17 00:00:00 2001 From: Andrew Cholewa Date: Mon, 23 Jan 2017 10:27:28 -0600 Subject: [PATCH 1/4] Makes TimedPhase auto-closeable. --This would allow us to wrap timed phases in a try-with-resources block: ```java try(TimedPhase phase = RequestLog.startTiming("timerAllTheThings") { doAllTheThings(); } ``` --This has several advantages over the current approach: 1. We always want to wrap the code that stops a timer in a finally block. Otherwise, the timer won't be stopped if we have an exception. try-with-resources makes that clean. 2. It reduces the chances of typos when starting and stopping timers. It also reduces the chances of people staring a timer and then forgetting to stop it. 3. It is more concise. --This has several limitations: 1. The minimum effort code to implement it is awkward. We'll need to do a much more significant (and not yet clear) refactor of RequestLog to handle this cleanly. 2. Timers that cross threads can't be handled this way. Those still need to be stopped and started manually. --Consequences that are more mixed: 1. It exposes a lot more of the inner workings of RequestLog. This could make it easier to customers to perform their own custom timings, but it also exposes code that is very easy to use incorrectly if you don't have a strong understanding of it. --- .../async/MetadataHttpResponseChannel.java | 2 +- .../webservice/data/HttpResponseChannel.java | 2 +- .../bard/webservice/logging/RequestLog.java | 101 ++++----------- .../bard/webservice/logging/TimedPhase.java | 119 ++++++++++++++++++ .../WeightCheckResponseProcessor.java | 4 +- .../WeightCheckResponseProcessorSpec.groovy | 6 +- 6 files changed, 153 insertions(+), 81 deletions(-) create mode 100644 fili-core/src/main/java/com/yahoo/bard/webservice/logging/TimedPhase.java 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/logging/RequestLog.java b/fili-core/src/main/java/com/yahoo/bard/webservice/logging/RequestLog.java index cd42f17e85..44c4c719b3 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 @@ -85,54 +85,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 +132,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 +161,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 +179,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 +190,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 +202,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 +218,7 @@ public static void startTiming(String timePhaseName) { current.times.put(timePhaseName, timePhase); } current.mostRecentTimer = timePhase; - timePhase.start(); + return timePhase.start(); } /** @@ -302,6 +246,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,7 +266,7 @@ public static void stopTiming(String timePhaseName) { LOG.warn("Tried to stop non-existent phase: {}", timePhaseName); return; } - timePhase.stop(); + timePhase.close(); } /** @@ -321,7 +274,7 @@ public static void stopTiming(String timePhaseName) { */ 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 +403,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/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 From 9195569be9204a58ae2f367411819ddaaed84e8e Mon Sep 17 00:00:00 2001 From: Andrew Cholewa Date: Mon, 23 Jan 2017 17:27:11 -0600 Subject: [PATCH 2/4] Deprecates `RequestLog::stopMostRecentTimer`. --- CHANGELOG.md | 15 ++++++++++----- .../yahoo/bard/webservice/logging/RequestLog.java | 5 +++++ 2 files changed, 15 insertions(+), 5 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index f4741adc93..d7e0a16796 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -40,6 +40,16 @@ Current ### 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`. + +- [`RequestLog::switchTiming` has been deprecated](https://github.com/yahoo/fili/pull/141) + - `RequestLog::switchTiming` is very context-dependent, and therefore brittle. In particular, adding any + additional timers inside code called by a timed block may result in the original timer not stopping + properly. All usages of `switchTiming` should be replaced with explicit calls to `RequestLog::startTiming` + and `RequestLog::stopTiming`. + ### Fixed: @@ -259,11 +269,6 @@ Changes: ### Deprecated: -- [`RequestLog::switchTiming` has been deprecated](https://github.com/yahoo/fili/pull/141) - - `RequestLog::switchTiming` is very context-dependent, and therefore brittle. In particular, adding any additional - timers inside code called by a timed block may result in the original timer not stopping properly. All usages of - `switchTiming` should be replaced with explicit calls to `RequestLog::startTiming` and `RequestLog::stopTiming`. - - [Dimension Field Tagging and Dynamic Dimension Field Serilization](https://github.com/yahoo/fili/pull/137) * Deprecated `DimensionsServlet::getDimensionFieldListSummaryView` and `DimensionsServlet::getDimensionFieldSummaryView` since there is no need for it anymore due to the change in serialization of `DimensionField` 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 44c4c719b3..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; @@ -271,7 +272,11 @@ public static void stopTiming(String timePhaseName) { /** * 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.getName()); From 320bb5e4b98253479d1847c5162a3a14ea640e20 Mon Sep 17 00:00:00 2001 From: Andrew Cholewa Date: Tue, 24 Jan 2017 15:52:29 -0600 Subject: [PATCH 3/4] Timings now use the try-with-resources blocks. --Those timers that are started and stopped in the same context now use try-with-resources blocks that start the timer. --- CHANGELOG.md | 5 ++ .../dimension/impl/LuceneSearchProvider.java | 11 ++--- .../bard/webservice/web/DataApiRequest.java | 46 ++++--------------- .../webservice/web/endpoints/DataServlet.java | 26 +++-------- .../web/filters/BardLoggingFilter.java | 15 +++--- 5 files changed, 32 insertions(+), 71 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index d7e0a16796..3a8fa28b25 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -378,6 +378,11 @@ New Capabilities & Enhancements: ### Changed: +- [`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. + - [Error messages generated during response processing include the request id.](https://github.com/yahoo/fili/pull/78) - [`DimensionStoreKeyUtils` now supports case sensitive row and column keys](https://github.com/yahoo/fili/pull/90) 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/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()); + } } /** From cf67dc0c33b007fcfa85239c5fa0fc35d05abedc Mon Sep 17 00:00:00 2001 From: Andrew Cholewa Date: Wed, 1 Feb 2017 11:33:43 -0600 Subject: [PATCH 4/4] Updates CHANGELOG. --- CHANGELOG.md | 21 +++++++++------------ 1 file changed, 9 insertions(+), 12 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 3a8fa28b25..e77481954f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -37,6 +37,10 @@ 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: @@ -44,13 +48,6 @@ Current - This method is a part of the infrastructure to support the recently deprecated `RequestLog::switchTiming`. -- [`RequestLog::switchTiming` has been deprecated](https://github.com/yahoo/fili/pull/141) - - `RequestLog::switchTiming` is very context-dependent, and therefore brittle. In particular, adding any - additional timers inside code called by a timed block may result in the original timer not stopping - properly. All usages of `switchTiming` should be replaced with explicit calls to `RequestLog::startTiming` - and `RequestLog::stopTiming`. - - ### Fixed: - Correcting error message logged when no table schema match is found @@ -269,6 +266,11 @@ Changes: ### Deprecated: +- [`RequestLog::switchTiming` has been deprecated](https://github.com/yahoo/fili/pull/141) + - `RequestLog::switchTiming` is very context-dependent, and therefore brittle. In particular, adding any additional + timers inside code called by a timed block may result in the original timer not stopping properly. All usages of + `switchTiming` should be replaced with explicit calls to `RequestLog::startTiming` and `RequestLog::stopTiming`. + - [Dimension Field Tagging and Dynamic Dimension Field Serilization](https://github.com/yahoo/fili/pull/137) * Deprecated `DimensionsServlet::getDimensionFieldListSummaryView` and `DimensionsServlet::getDimensionFieldSummaryView` since there is no need for it anymore due to the change in serialization of `DimensionField` @@ -378,11 +380,6 @@ New Capabilities & Enhancements: ### Changed: -- [`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. - - [Error messages generated during response processing include the request id.](https://github.com/yahoo/fili/pull/78) - [`DimensionStoreKeyUtils` now supports case sensitive row and column keys](https://github.com/yahoo/fili/pull/90)