Fix some timers. #141

archolewa · 2017-01-18T20:19:21Z

--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.

michael-mclawhorn · 2017-01-18T22:04:55Z

Reading this code makes me all sad inside.

archolewa · 2017-01-18T22:14:07Z

Writing this code a while back filled me with RAGE.

michael-mclawhorn · 2017-01-18T22:17:51Z

👍

cdeszaq

Removing the timing around the request makes sense. But we need to figure out what's going on with the timer you're seeing not get stopped. I'm guessing there's a response being sent from a requestMapper that's not playing nice with timers. If that's the case, we need to update docs somewhere to reflect that implicit requirement of request mappers.

cdeszaq · 2017-01-18T22:27:21Z

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");


Why was this needed? The call on line 374 should switch from the timer that was open to the next one. If anything, perhaps we should wrap a timing phase around the request mapping (which would also stop this one). I guess my question is: Under what conditions was this timer not being stopped, since it looks like this shouldn't be a problem based on the code in this file.

Oh, that's right, I forgot that switching also stops timers. I was doing this in between another task that had a lot of "hurry up and wait" so I kept losing context.

Hmm. I'll need to do some more digging. I know that we're having a similar problem with the hydrating dimension rows timer in Lucene. Despite the code ostensibly being there, it doesn't seem like we are actually executing the line that starts the timer.

I know why switchTimer isn't working. Here's the implementation:

stopMostRecentTimer(); startTiming(nextPhase);

However, the DataApiRequest timer is no longer the most recent timer, because of all the timings we added to the DataApiRequest. So, switchTimer doesn't do what you think it should if you have timings happening inside any method calls between startTimer and switchTimer.

growls I always hated this behavior.

I'm telling you, when someone says "X is convenient" you should hear "X will cause unexpected bugs a few refactors from now."

--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.

--`RequestLog::switchTiming` works by stopping the most recent timer, and then starting the specified timer. As a result, we can fail to stop a timer A if we start and stop timer B inside a method invoked while timer A is running. As a result, in order to ensure that all of your timers are working correctly, you need to be cognizant of the internal workings of every method you invoke within the timed block. --Therefore, in an effort to make timed code more modular, we've removed the `RequestLog::switchTiming` method, and replaced all instances of it with try-finally blocks that explicitly stop and start each timer. It's ugly, but it's also much less brittle.

cdeszaq

Just a few tweaks, and making sure we didn't lose a timer. Otherwise, this is looking really good, thanks!

cdeszaq · 2017-01-23T15:03:42Z

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

-     *
-     * @param nextPhase  the name of the stopwatch to be started
-     */
-    public static void switchTiming(String nextPhase) {


Should deprecate and call out in changelog, not directly remove.

cdeszaq · 2017-01-23T15:04:25Z

fili-core/src/main/java/com/yahoo/bard/webservice/web/endpoints/DataServlet.java


            if (requestMapper != null) {
                apiRequest = (DataApiRequest) requestMapper.apply(apiRequest, containerRequestContext);
            }

-            RequestLog.switchTiming("DruidQueryMerge");
+            RequestLog.startTiming("DruidQueryMerge");
+            TemplateDruidQuery templateQuery;
            // Build the query template


You're gonna hate me for this, but in these refactor spots, can we float the comment to the start of the "block" (ie. above the start of the timer)? Having it in the middle is slightly confusing.

cdeszaq · 2017-01-23T15:05:06Z

fili-core/src/main/java/com/yahoo/bard/webservice/web/endpoints/DataServlet.java

-            RequestLog.switchTiming("logRequestMetrics");
-            logRequestMetrics(apiRequest, readCache, druidQuery);
-            RequestLog.record(new DruidFilterInfo(apiRequest.getFilter()));
-            RequestLog.switchTiming(REQUEST_WORKFLOW_TIMER);


We've lost the start to the request workflow timer I think.

Do we want to have tests to verify that the request log is correctly stimulated?

We probably do. Especially since I looked through the logs and it looks like there are a few places where we aren't properly stopping timers (the JobsServlet and I don't think our TestDruidWebService is stopping the request workflow timer correctly).

I tried poking at fixing those problems, but my quick fix in the TestDruidWebService didn't seem to stop all the warnings about the request workflow timer, and the JobsServlet desperately needs to be cleaned up. We start and stop timers all over the place. Since that was more than I wanted to take on right now, I dropped the effort.

The tricky part is that I'm not sure how to do that test. Most methods that run timers, we could probably check easily enough that all the appropriate timers have been stopped. Not sure how to verify that a timer has been started. Especially in the DataServlet.

Ideally we'd use a mock, but RequestLog is statically accessible.

Well, we know a technique for fixing the static dependency, but it's a bigger effort than this PR.
Do we care about timers that have started but not stopped?

Well, if the timers haven't been stopped, then when we go to log their durations, we'll get incorrect numbers.

cdeszaq

Only the last little thing about moving the changelog comment to the right section.

cdeszaq · 2017-01-23T16:38:54Z

CHANGELOG.md

@@ -49,10 +49,11 @@ Current

 ### Changed:

- [`RequestLog::switchTiming` has been removed]((https://github.com/yahoo/fili/pull/141)
+- [`RequestLog::switchTiming` has been deprecated]((https://github.com/yahoo/fili/pull/141)


Need to call out deprecation in deprecation section of change log

cdeszaq · 2017-01-23T16:40:11Z

CHANGELOG.md

@@ -49,6 +49,16 @@ Current

 ### Changed:

+- [`RequestLog::switchTiming` has been deprecated]((https://github.com/yahoo/fili/pull/141)


Not sure where the other comment I left went, but this note should move into the deprecated section

michael-mclawhorn · 2017-01-23T17:25:25Z

reaffirming my 👍

archolewa force-pushed the fix-timings branch 2 times, most recently from dfda64d to e8c1b8a Compare January 18, 2017 21:43

cdeszaq reviewed Jan 18, 2017

View reviewed changes

archolewa force-pushed the fix-timings branch 3 times, most recently from 4347632 to e82d0f6 Compare January 20, 2017 19:51

archolewa force-pushed the fix-timings branch from e82d0f6 to cc328de Compare January 20, 2017 20:02

cdeszaq requested changes Jan 23, 2017

View reviewed changes

Andrew Cholewa added 2 commits January 23, 2017 09:28

Deprecated RequestLog::switchTiming.

42cb086

Addressed comments.

dcc1011

cdeszaq approved these changes Jan 23, 2017

View reviewed changes

Addressed comments.

ca6135d

cdeszaq merged commit 351c49d into master Jan 23, 2017

cdeszaq deleted the fix-timings branch January 23, 2017 18:20

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix some timers. #141

Fix some timers. #141

archolewa commented Jan 18, 2017

michael-mclawhorn commented Jan 18, 2017

archolewa commented Jan 18, 2017

michael-mclawhorn commented Jan 18, 2017

cdeszaq left a comment

cdeszaq Jan 18, 2017

archolewa Jan 19, 2017 •

edited

Loading

archolewa Jan 19, 2017 •

edited

Loading

archolewa Jan 20, 2017

michael-mclawhorn Jan 20, 2017

archolewa Jan 20, 2017

cdeszaq left a comment

cdeszaq Jan 23, 2017

cdeszaq Jan 23, 2017

cdeszaq Jan 23, 2017

archolewa Jan 23, 2017

michael-mclawhorn Jan 23, 2017

archolewa Jan 23, 2017

michael-mclawhorn Jan 23, 2017

archolewa Jan 23, 2017

cdeszaq left a comment

cdeszaq Jan 23, 2017

cdeszaq Jan 23, 2017

michael-mclawhorn commented Jan 23, 2017

		@@ -49,6 +49,16 @@ Current

		### Changed:

		- [`RequestLog::switchTiming` has been deprecated]((https://github.com/yahoo/fili/pull/141)

Fix some timers. #141

Fix some timers. #141

Conversation

archolewa commented Jan 18, 2017

michael-mclawhorn commented Jan 18, 2017

archolewa commented Jan 18, 2017

michael-mclawhorn commented Jan 18, 2017

cdeszaq left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

archolewa Jan 19, 2017 • edited Loading

Choose a reason for hiding this comment

archolewa Jan 19, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cdeszaq left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cdeszaq left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

michael-mclawhorn commented Jan 23, 2017

archolewa Jan 19, 2017 •

edited

Loading

archolewa Jan 19, 2017 •

edited

Loading