Makes TimedPhase auto-closeable. #143
+192
−152
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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. | ||
| * <p> | ||
| * 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; | ||
|
There was a problem hiding this comment. I think I tried playing around with using 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;
}There was a problem hiding this comment. 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. There was a problem hiding this comment. 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. |
||
|
|
||
| /** | ||
| * 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. | ||
| * <p> | ||
| * 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. | ||
| * <p> | ||
| * 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. | ||
| * <p> | ||
| * 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(); | ||
| } | ||
| } | ||
Oops, something went wrong.
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
If we make "stop" convert to doing the registering, calling "close" is likely not needed, but "stop" will be.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
closehas to do the registering anyway, because that's the method invoked when thetry-with-resourcesblock ends. So even if we change howstopworks, and hadclosedelegate tostop, we still wouldn't need to change this invocation.There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Plus we shouldn't change this from
closetostop. In my opinion,RequestLog::stopTimingshould 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).