Makes TimedPhase auto-closeable. #143

archolewa · 2017-01-23T16:36:33Z

--This would allow us to wrap timed phases in a try-with-resources
block:

   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.

archolewa · 2017-01-23T16:52:47Z

There are a couple of changes here:

I moved TimedPhase out into its own class, and made it beanlike. This isn't strictly necessary, but makes it a little bit cleaner IMO since it can now show up in the code independent of the RequestLog.
Stopping a timer and storing its duration in the RequestLog have been split into two steps:
1. Stop the timer.
2. Store the timer's final time in the RequestLog's registery.

This was necessary because TimedPhase no longer has insight into the guts of RequestLog.

Both of these steps have been encapsulated in TimedPhase::close, which is automatically invoked at the end of a try-with-resources block with the finally semantics.

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

I like this approach a lot

cdeszaq

Just a few small things.

Also, ChangeLog needed.

cdeszaq · 2017-01-23T19:59:39Z

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

@@ -0,0 +1,88 @@
+// Copyright 2016 Yahoo Inc.


fist shake JANUARRYY!!!!

cdeszaq · 2017-01-23T20:01:29Z

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

+     * Stop the phase.
+     */
+    public void stop() {
+        if (start == 0) {


Would be better to convert to use the isStarted method

cdeszaq · 2017-01-23T20:01:32Z

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

+     * Start the phase.
+     */
+    public void start() {
+        if (start != 0) {


Would be better to convert to use the isStarted method

cdeszaq · 2017-01-23T20:04:12Z

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

@@ -275,6 +231,7 @@ public static void startTiming(String timePhaseName) {
        }
        current.mostRecentTimer = timePhase;
        timePhase.start();
+        return timePhase;


Just make TimedPhase::start return itself?

cdeszaq · 2017-01-23T20:07:17Z

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

-                return;
-            }
-            duration += System.nanoTime() - start;
-            REGISTRY.timer(name).update(duration, TimeUnit.NANOSECONDS);


I think this is getting lost. It may very well be that TimedPhase::stop needs to do the registration that TimedPhase::close is doing? Otherwise, I think there's a gap where things could be lost.

Or, to put it a different way, stop did the registering before, and now only close does it. Since stop was private, I don't know how much impact it will really have, but it's worth noting.

I'm not sure I understand your concern about registering "getting lost." It's now invoked as part of the TimedPhase::close, which is being called by RequestLog::stopTiming. So the behavior of the public interface hasn't changed. So this change will only affect people if they are doing Unsupported Things.

Ok, I figured out what the problem was that I was worried about: Since stop is a public method, it's not clear what the difference between stop and close is, so there's a possibility that someone will call stop, but not close, which would result in not recording that chunk of time in the RequestLog.

I see the value in having stop be public, and separate from close, since it allows for accruing time in chunks, but only recording it at the end, but I think some more documentation is needed on stop (and possibly on close) to indicate that it's just stopping the timer, and not registering it with RequestLog.

It also seems like there may be a mismatch in responsibilities, because if someone wanted to do something like:

start -> stop -> start -> stop -> close

they would get a warning logged, since close tries to stop. Perhaps close just needs to check !isStarted() before calling stop()?

cdeszaq · 2017-01-23T20:09:21Z

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

@@ -308,15 +277,15 @@ public static void stopTiming(String timePhaseName) {
            LOG.warn("Tried to stop non-existent phase: {}", timePhaseName);
            return;
        }
-        timePhase.stop();
+        timePhase.close();


If we make "stop" convert to doing the registering, calling "close" is likely not needed, but "stop" will be.

close has to do the registering anyway, because that's the method invoked when the try-with-resources block ends. So even if we change how stop works, and had close delegate to stop, we still wouldn't need to change this invocation.

Plus we shouldn't change this from close to stop. In my opinion, RequestLog::stopTiming should have the same semantics as what the try-with-resources block does (with the exception of the existence check that the try-with-resources doesn't have to worry about).

archolewa · 2017-01-23T23:28:22Z

Since there seems to be strong support for this change, I'm going to flesh it out into a proper PR tomorrow (updating timers that could benefit from it, adding a CHANGELOG, etc).

I'm also going to squash the commits that are currently here down into logical commits to facilitate a proper review.

michael-mclawhorn · 2017-02-01T17:26:30Z

👍

cdeszaq · 2017-03-01T15:12:36Z

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

+
+    /**
+     * Constructor.
+     * Times are in nanoseconds.


Why is this here? There is nothing time-related in the constructor. Should this be moved up to the class-level doc?

cdeszaq · 2017-03-01T15:37:56Z

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

-                return;
-            }
-            duration += System.nanoTime() - start;
-            REGISTRY.timer(name).update(duration, TimeUnit.NANOSECONDS);


Ok, I figured out what the problem was that I was worried about: Since stop is a public method, it's not clear what the difference between stop and close is, so there's a possibility that someone will call stop, but not close, which would result in not recording that chunk of time in the RequestLog.

I see the value in having stop be public, and separate from close, since it allows for accruing time in chunks, but only recording it at the end, but I think some more documentation is needed on stop (and possibly on close) to indicate that it's just stopping the timer, and not registering it with RequestLog.

It also seems like there may be a mismatch in responsibilities, because if someone wanted to do something like:

start -> stop -> start -> stop -> close

they would get a warning logged, since close tries to stop. Perhaps close just needs to check !isStarted() before calling stop()?

cdeszaq · 2017-03-01T15:43:59Z

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

+        return TimeUnit.NANOSECONDS;
+    }
+
+    public boolean isStarted() {


This may seem stupid, but should we change the name of this method to isRunning? We seem to be using it to indicate if this TimedPhase is currently running or not, and isStarted feels more like a "once I've been started, I've always been started" sort of thing, where as running / stopped feels more like a toggleable state.

Obviously this is a small thing, but every time I see isStarted, I noticed I had to mentally pause and convert to isRunning.

cdeszaq · 2017-03-01T16:06:18Z

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

+    }
+
+    public long getDuration() {
+        return duration;


There are two places in RequestLog where the duration is retrieved, and those places are just after an isStarted check. Could we move that isStarted check / warning log into this getter so that the RequestLog doesn't have to worry about it?

cdeszaq · 2017-03-01T16:10:38Z

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

+
+    private final String name;
+    private long start;
+    private long duration;


I think start and duration need to be made thread-safe (likely with AtomicLongs)... It wasn't an issue before, because TimedPhase was encapsulated within the RequestLog, which was a ThreadLocal and was never able to exist on more than 1 thread at a time, but TimedPhase is now it's own thing, and there's a possibility of sharing them across threads.

I tried playing around with using AtomicLong for these variables a little bit, and it's not hard to retain the existing semantics, though it did make me think about if we wanted to maintain the existing semantics around multiple consecutive starts / stops, especially in the new world of being across threads. No good solutions to this came to mind immediately, so it may make sense to add a cautionary note to the class-level doc for TimedPhase indicating the possible race condition of starting and stopping the same phase on multiple threads.

Anyway, here's the relevant results of my exploration, in case they help:

private static final long NOT_RUNNING = 0; private final String name; private final AtomicLong start = new AtomicLong(); private final AtomicLong duration = new AtomicLong(); /** * Start the phase. * * @return This phase after being started */ public TimedPhase start() { if (!start.compareAndSet(NOT_RUNNING, System.nanoTime())) { LOG.warn("Tried to start timer that is already running: {}", name); } return this; } /** * Stop the phase. */ public void stop() { long started = start.getAndUpdate(ignoredCurrent -> NOT_RUNNING); if (started == 0) { LOG.warn("Tried to stop timer that has not been started: {}", name); return; } duration.addAndGet(System.nanoTime() - started); } public long getDuration() { return duration.get(); } public boolean isStarted() { return start.get() != 0; }

I'm ok with making it thread safe, especially since many of these timers are stopped on a different thread than they're started (the request vs response thread). Rethinking the semantics is outside the scope of this PR though, I think.

Actually, after playing with it a little bit, I think I'm going to punt on this, largely because validating whether a timer is running outside of this class or not becomes a lot trickier in a multi-threaded scenario.

cdeszaq · 2017-03-01T16:15:17Z

A few small things, and medium thing (the warning logger), and a large thing (the thread safety). I'm OK punting on the TimedPhase thread safety (I think) as long as we clearly note that it's not a thread-safe class if both classes are starting / stopping. It would be great to close that gap, but I'm happy to take the clarity offered by it being closable, and coming back to making TimedPhase thread-safe. (A techdebt ticket might be a good idea)

Other than the thread safety issue, if everything else is updated, this is good to merge.

archolewa · 2017-03-01T17:02:48Z

Ticket to revisit making timers thread-safe: #185

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

--Those timers that are started and stopped in the same context now use try-with-resources blocks that start the timer.

archolewa force-pushed the timing-phase-auto-closeable branch from eb74806 to 8ee84f1 Compare January 23, 2017 16:42

archolewa force-pushed the timing-phase-auto-closeable branch from 8ee84f1 to 0fa8df4 Compare January 23, 2017 16:53

archolewa added the DESIGN label Jan 23, 2017

cdeszaq requested changes Jan 23, 2017

View reviewed changes

archolewa force-pushed the timing-phase-auto-closeable branch from 0fa8df4 to dec9756 Compare January 23, 2017 20:43

archolewa force-pushed the timing-phase-auto-closeable branch from aaaf44a to bcefb9a Compare January 24, 2017 21:53

archolewa added NEED 2 REVIEWS REVIEWABLE and removed DESIGN labels Jan 24, 2017

archolewa mentioned this pull request Jan 27, 2017

Expose the request phase durations stored by RequestLog #100

Closed

michael-mclawhorn added NEED 1 REVIEW and removed NEED 2 REVIEWS labels Feb 1, 2017

michael-mclawhorn self-requested a review February 1, 2017 17:30

michael-mclawhorn approved these changes Feb 1, 2017

View reviewed changes

archolewa force-pushed the timing-phase-auto-closeable branch from bcefb9a to c207831 Compare February 1, 2017 17:34

aklish approved these changes Feb 28, 2017

View reviewed changes

archolewa force-pushed the timing-phase-auto-closeable branch from c207831 to 8f514bf Compare February 28, 2017 18:38

cdeszaq reviewed Mar 1, 2017

View reviewed changes

cdeszaq approved these changes Mar 1, 2017

View reviewed changes

archolewa force-pushed the timing-phase-auto-closeable branch from 067af4d to ed75539 Compare March 1, 2017 16:55

archolewa force-pushed the timing-phase-auto-closeable branch from ed75539 to d1daab8 Compare March 1, 2017 17:12

archolewa added 4 commits March 1, 2017 11:24

Deprecates RequestLog::stopMostRecentTimer.

9195569

Timings now use the try-with-resources blocks.

320bb5e

--Those timers that are started and stopped in the same context now use try-with-resources blocks that start the timer.

Updates CHANGELOG.

cf67dc0

archolewa force-pushed the timing-phase-auto-closeable branch from d1daab8 to cf67dc0 Compare March 1, 2017 17:24

archolewa merged commit 25057d1 into master Mar 1, 2017

archolewa deleted the timing-phase-auto-closeable branch March 1, 2017 18:11

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Makes TimedPhase auto-closeable. #143

Makes TimedPhase auto-closeable. #143

archolewa commented Jan 23, 2017

archolewa commented Jan 23, 2017

michael-mclawhorn commented Jan 23, 2017

cdeszaq left a comment

cdeszaq Jan 23, 2017

archolewa Jan 23, 2017

cdeszaq Jan 23, 2017

cdeszaq Jan 23, 2017

cdeszaq Jan 23, 2017

cdeszaq Jan 23, 2017

archolewa Jan 23, 2017

cdeszaq Mar 1, 2017

cdeszaq Jan 23, 2017

archolewa Jan 23, 2017 •

edited

archolewa Jan 23, 2017 •

edited

archolewa commented Jan 23, 2017

michael-mclawhorn commented Feb 1, 2017

cdeszaq Mar 1, 2017

cdeszaq Mar 1, 2017

cdeszaq Mar 1, 2017

archolewa Mar 1, 2017

cdeszaq Mar 1, 2017

cdeszaq Mar 1, 2017

archolewa Mar 1, 2017

archolewa Mar 1, 2017

cdeszaq commented Mar 1, 2017

archolewa commented Mar 1, 2017

Makes TimedPhase auto-closeable. #143

Makes TimedPhase auto-closeable. #143

Conversation

archolewa commented Jan 23, 2017

archolewa commented Jan 23, 2017

michael-mclawhorn commented Jan 23, 2017

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

Choose a reason for hiding this comment

archolewa Jan 23, 2017 • edited

Choose a reason for hiding this comment

archolewa Jan 23, 2017 • edited

Choose a reason for hiding this comment

archolewa commented Jan 23, 2017

michael-mclawhorn commented Feb 1, 2017

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 commented Mar 1, 2017

archolewa commented Mar 1, 2017

archolewa Jan 23, 2017 •

edited

archolewa Jan 23, 2017 •

edited