Skip to content

Commit

Permalink
Makes TimedPhase auto-closeable.
Browse files Browse the repository at this point in the history
--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.
  • Loading branch information
archolewa committed Jan 23, 2017
1 parent 2ae0605 commit 0fa8df4
Show file tree
Hide file tree
Showing 2 changed files with 113 additions and 56 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -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.
*/
Expand Down Expand Up @@ -184,15 +136,15 @@ private Map<String, Long> getDurations() {
.stream()
.peek(
phase -> {
if (phase.start != 0) {
if (phase.isStarted()) {
LOG.warn(
"Exporting duration while timer is running. Measurement might be wrong: {}",
phase.name
phase.getName()
);
}
}
)
.collect(Collectors.toMap(phase -> phase.name, phase -> phase.duration));
.collect(Collectors.toMap(TimedPhase::getName, TimedPhase::getDuration));
}

/**
Expand Down Expand Up @@ -250,18 +202,22 @@ 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());
}

/**
* Start a stopwatch.
* 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) {
Expand All @@ -275,6 +231,7 @@ public static void startTiming(String timePhaseName) {
}
current.mostRecentTimer = timePhase;
timePhase.start();
return timePhase;
}

/**
Expand All @@ -297,6 +254,18 @@ 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) {
if (stoppedPhase.isStarted()) {
LOG.warn("Timer '{}' is still running. Timings may be incorrect.", stoppedPhase.getName());
}
RequestLog.REGISTRY.timer(stoppedPhase.getName()).update(stoppedPhase.getDuration(), stoppedPhase.getUnit());
}

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

/**
* Stop the most recent stopwatch.
*/
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.");
}
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,88 @@
// Copyright 2016 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.
*/
public class TimedPhase implements AutoCloseable {
private static final Logger LOG = LoggerFactory.getLogger(TimedPhase.class);

private final String name;
private final TimeUnit unit;
private long start;
private long duration;

/**
* Constructor.
*
* @param name Name of the phase
* @param unit The timer's units
*/
public TimedPhase(String name, TimeUnit unit) {
this.name = name;
this.unit = unit;
}

/**
* Constructor.
* Times in nanoseconds.
*
* @param name Name of the phase
*/
public TimedPhase(String name) {
this(name, TimeUnit.NANOSECONDS);
}

/**
* Start the phase.
*/
public void start() {
if (start != 0) {
LOG.warn("Tried to start timer that is already running: {}", name);
return;
}
start = System.nanoTime();
}

/**
* Stop the phase.
*/
public void stop() {
if (start == 0) {
LOG.warn("Tried to stop timer that has not been started: {}", name);
return;
}
duration += System.nanoTime() - start;
start = 0;
}

public long getDuration() {
return duration;
}

public String getName() {
return name;
}

public TimeUnit getUnit() {
return unit;
}

public boolean isStarted() {
return start != 0;
}

@Override
public void close() {
stop();
RequestLog.registerTime(this);
}
}

0 comments on commit 0fa8df4

Please sign in to comment.