From dfda64d44bab39dbbef10a3fa87cc7003df840d7 Mon Sep 17 00:00:00 2001 From: Andrew Cholewa Date: Wed, 18 Jan 2017 14:06:07 -0600 Subject: [PATCH] Fix some timers. --We forgot to stop the `DataApiRequest` timer. --When timing the posting of the Druid Query we failed to account for the thread hopping during asynchronous programming. As a result, not only were we failing to stop the timer in the correct instance of the RequestLog (the one that is used by the response handling thread), but we also attempted to stop a timer in a RequestLog that has since been cleared. So we end up with two warnings: One for attempting to stop a timer that doesn't exist, and one for logging a timer that was never stopped. Since there isn't a good way to time just the posting of the druid query, and it probably isn't necessary anyway, the timing has been removed. --- CHANGELOG.md | 7 ++ .../client/impl/AsyncDruidWebServiceImpl.java | 79 +++++++++---------- .../webservice/web/endpoints/DataServlet.java | 1 + 3 files changed, 45 insertions(+), 42 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 6f6eafa542..209f4d4d20 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -44,6 +44,10 @@ Current ### Changed: +- [The druid query posting timer has been removed](https://github.com/yahoo/fili/pull/141) + * There wasn't really a good way of stopping timing only the posting itself. Since the timer is + probably not that useful, it has been removed. + - [MetricMaker cleanup and simplification](https://github.com/yahoo/fili/pull/127) * Simplified raw aggregation makers * `ConstantMaker` now throws an `IllegalArgumentException` wrapping the raw NumberFormatException on a bad argument @@ -197,6 +201,9 @@ Current ### Fixed: +- [Stopped `DataApiRequest` timer](https://github.com/yahoo/fili/pull/141): + * Stopping the `DataApiRequest` timer that we forgot to stop + - [Added missing coverage for `ThetaSketchEstimate` unwrapping in `MetricMaker.getSketchField`](https://github.com/yahoo/fili/pull/128) - [`DataSource::getNames` now returns Fili identifiers, not fact store identifiers](https://github.com/yahoo/fili/pull/125/files) diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/druid/client/impl/AsyncDruidWebServiceImpl.java b/fili-core/src/main/java/com/yahoo/bard/webservice/druid/client/impl/AsyncDruidWebServiceImpl.java index 7e5631114d..0bc025afaa 100644 --- a/fili-core/src/main/java/com/yahoo/bard/webservice/druid/client/impl/AsyncDruidWebServiceImpl.java +++ b/fili-core/src/main/java/com/yahoo/bard/webservice/druid/client/impl/AsyncDruidWebServiceImpl.java @@ -297,52 +297,47 @@ public void postDruidQuery( DruidQuery druidQuery ) { long seqNum = druidQuery.getContext().getSequenceNumber(); - RequestLog.startTiming("PostingDruidQuery" + seqNum); + String entityBody; + RequestLog.startTiming("DruidQuerySerializationSeq" + 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); - } + entityBody = writer.writeValueAsString(druidQuery); + } catch (JsonProcessingException e) { + throw new IllegalStateException(e); + } finally { + RequestLog.stopTiming("DruidQuerySerializationSeq" + seqNum); + } - 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); - } + long totalQueries = druidQuery.getContext().getNumberOfQueries(); + String format = String.format("%%0%dd", String.valueOf(totalQueries).length()); + String timerName; + AtomicLong 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); + 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); } + + 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 + ); } @Override 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 ef99759a2b..edcedac1c8 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 @@ -365,6 +365,7 @@ public void getData( uriInfo, this ); + RequestLog.stopTiming("DataApiRequest"); if (requestMapper != null) { apiRequest = (DataApiRequest) requestMapper.apply(apiRequest, containerRequestContext);