    001    package org.junit.rules;
    002
    003    import org.junit.AssumptionViolatedException;
    004    import org.junit.runner.Description;
    005    import org.junit.runners.model.Statement;
    006
    007    import 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     */
    079    public 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    }