001package org.junit.rules;
002
003import org.junit.AssumptionViolatedException;
004import org.junit.runner.Description;
005import org.junit.runners.model.Statement;
006
007import java.util.concurrent.TimeUnit;
008
009/**
010 * The Stopwatch Rule notifies one of its own protected methods of the time spent by a test.
011 *
012 * <p>Override them to get the time in nanoseconds. For example, this class will keep logging the
013 * time spent by each passed, failed, skipped, and finished test:
014 *
015 * <pre>
016 * public static class StopwatchTest {
017 *     private static final Logger logger = Logger.getLogger(&quot;&quot;);
018 *
019 *     private static void logInfo(Description description, String status, long nanos) {
020 *         String testName = description.getMethodName();
021 *         logger.info(String.format(&quot;Test %s %s, spent %d microseconds&quot;,
022 *                                   testName, status, TimeUnit.NANOSECONDS.toMicros(nanos)));
023 *     }
024 *
025 *     &#064;Rule
026 *     public Stopwatch stopwatch = new Stopwatch() {
027 *         &#064;Override
028 *         protected void succeeded(long nanos, Description description) {
029 *             logInfo(description, &quot;succeeded&quot;, nanos);
030 *         }
031 *
032 *         &#064;Override
033 *         protected void failed(long nanos, Throwable e, Description description) {
034 *             logInfo(description, &quot;failed&quot;, nanos);
035 *         }
036 *
037 *         &#064;Override
038 *         protected void skipped(long nanos, AssumptionViolatedException e, Description description) {
039 *             logInfo(description, &quot;skipped&quot;, nanos);
040 *         }
041 *
042 *         &#064;Override
043 *         protected void finished(long nanos, Description description) {
044 *             logInfo(description, &quot;finished&quot;, nanos);
045 *         }
046 *     };
047 *
048 *     &#064;Test
049 *     public void succeeds() {
050 *     }
051 *
052 *     &#064;Test
053 *     public void fails() {
054 *         fail();
055 *     }
056 *
057 *     &#064;Test
058 *     public void skips() {
059 *         assumeTrue(false);
060 *     }
061 * }
062 * </pre>
063 *
064 * An example to assert runtime:
065 * <pre>
066 * &#064;Test
067 * public void performanceTest() throws InterruptedException {
068 *     long delta = 30;
069 *     Thread.sleep(300L);
070 *     assertEquals(300d, stopwatch.runtime(MILLISECONDS), delta);
071 *     Thread.sleep(500L);
072 *     assertEquals(800d, stopwatch.runtime(MILLISECONDS), delta);
073 * }
074 * </pre>
075 *
076 * @author tibor17
077 * @since 4.12
078 */
079public class Stopwatch implements TestRule {
080    private final Clock clock;
081    private volatile long startNanos;
082    private volatile long endNanos;
083
084    public Stopwatch() {
085        this(new Clock());
086    }
087
088    Stopwatch(Clock clock) {
089        this.clock = clock;
090    }
091
092    /**
093     * Gets the runtime for the test.
094     *
095     * @param unit time unit for returned runtime
096     * @return runtime measured during the test
097     */
098    public long runtime(TimeUnit unit) {
099        return unit.convert(getNanos(), TimeUnit.NANOSECONDS);
100    }
101
102    /**
103     * Invoked when a test succeeds
104     */
105    protected void succeeded(long nanos, Description description) {
106    }
107
108    /**
109     * Invoked when a test fails
110     */
111    protected void failed(long nanos, Throwable e, Description description) {
112    }
113
114    /**
115     * Invoked when a test is skipped due to a failed assumption.
116     */
117    protected void skipped(long nanos, AssumptionViolatedException e, Description description) {
118    }
119
120    /**
121     * Invoked when a test method finishes (whether passing or failing)
122     */
123    protected void finished(long nanos, Description description) {
124    }
125
126    private long getNanos() {
127        if (startNanos == 0) {
128            throw new IllegalStateException("Test has not started");
129        }
130        long currentEndNanos = endNanos; // volatile read happens here
131        if (currentEndNanos == 0) {
132          currentEndNanos = clock.nanoTime();
133        }
134
135        return currentEndNanos - startNanos;
136    }
137
138    private void starting() {
139        startNanos = clock.nanoTime();
140        endNanos = 0;
141    }
142
143    private void stopping() {
144        endNanos = clock.nanoTime();
145    }
146
147    public final Statement apply(Statement base, Description description) {
148        return new InternalWatcher().apply(base, description);
149    }
150
151    private class InternalWatcher extends TestWatcher {
152
153        @Override protected void starting(Description description) {
154            Stopwatch.this.starting();
155        }
156
157        @Override protected void finished(Description description) {
158            Stopwatch.this.finished(getNanos(), description);
159        }
160
161        @Override protected void succeeded(Description description) {
162            Stopwatch.this.stopping();
163            Stopwatch.this.succeeded(getNanos(), description);
164        }
165
166        @Override protected void failed(Throwable e, Description description) {
167            Stopwatch.this.stopping();
168            Stopwatch.this.failed(getNanos(), e, description);
169        }
170
171        @Override protected void skipped(AssumptionViolatedException e, Description description) {
172            Stopwatch.this.stopping();
173            Stopwatch.this.skipped(getNanos(), e, description);
174        }
175    }
176
177    static class Clock {
178
179        public long nanoTime() {
180            return System.nanoTime();
181        }
182    }
183}