Time Watcher

src/main/java/org/junit/rules/TimeWatcher.java

@@ -0,0 +1,140 @@
+package org.junit.rules;
+
+import org.junit.internal.AssumptionViolatedException;
+import org.junit.runner.Description;
+
+/**
+ * The TimeWatcher Rule notifies one of own protected methods of the time spent by a test.<p/>
+ * Override them to get the time in nanoseconds. For example, this class will keep logging the
+ * time spent by each passing, failing and skipped test:
+ *
+ * <pre>
+ * public static class TimeWatcherTest {
+ *  private static final Logger logger = Logger.getLogger(&quot;&quot;);
+ *
+ *  private static void logInfo(String testName, String status, long nanos) {
+ *      logger.info(String.format(&quot;Test %s %s, spent %d microseconds&quot;,
+ *                                  testName, status, TimeWatcher.toMicros(nanos)));
+ *  }
+ *
+ *  &#064;Rule
+ *  public TimeWatcher timeWatcher= new TimeWatcher() {
+ *      &#064;Override
+ *      protected void succeeded(long nanos, Description description) {
+ *          logInfo(description.getMethodName(), &quot;succeeded&quot;, nanos);
+ *      }
+ *
+ *      &#064;Override
+ *      protected void failed(long nanos, Throwable e, Description description) {
+ *          logInfo(description.getMethodName(), &quot;failed&quot;, nanos);
+ *      }
+ *
+ *      &#064;Override
+ *      protected void skipped(long nanos, AssumptionViolatedException e, Description description) {
+ *          logInfo(description.getMethodName(), &quot;skipped&quot;, nanos);
+ *      }
+ *
+ *      &#064;Override
+ *      protected void finished(long nanos, Description description) {
+ *          logInfo(description.getMethodName(), &quot;finished&quot;, nanos);
+ *      }
+ *  };
+ *
+ *  &#064;Test
+ *  public void succeeds() {
+ *  }
+ *
+ *  &#064;Test
+ *  public void fails() {
+ *      fail();
+ *  }
+ *
+ *  &#064;Test
+ *  public void skips() {
+ *      assumeTrue(false);
+ *  }
+ * }
+ * </pre>
+ *
+ * @author tibor17
+ * @since 4.12
+ */
+public class TimeWatcher extends TestWatcher {
+    private volatile long startNanos = 0L;
+    private volatile long endNanos = 0L;
+
+    /**
+     * Invoked when a test succeeds
+     */
+    protected void succeeded(long nanos, Description description) {
+    }
+
+    /**
+     * Invoked when a test fails
+     */
+    protected void failed(long nanos, Throwable e, Description description) {
+    }
+
+    /**
+     * Invoked when a test is skipped due to a failed assumption.
+     */
+    protected void skipped(long nanos, AssumptionViolatedException e, Description description) {
+    }
+
+    /**
+     * Invoked when a test method finishes (whether passing or failing)
+     */
+    protected void finished(long nanos, Description description) {
+    }
+
+    /**
+     * @param nanos time in nanoseconds
+     * @return time converted to microseconds
+     */
+    public static long toMicros(long nanos) {
+        return nanos / (1000);
+    }
+
+    /**
+     * @param nanos time in nanoseconds
+     * @return time converted to milliseconds
+     */
+    public static long toMillis(long nanos) {
+        return nanos / (1000 * 1000);
+    }
+
+    /**
+     * @param nanos time in nanoseconds
+     * @return time converted to seconds
+     */
+    public static long toSeconds(long nanos) {
+        return nanos / (1000 * 1000 * 1000);
+    }
+
+    private long getNanos() {
+        return endNanos - startNanos;
+    }
+
+    @Override final protected void succeeded(Description description) {
+        endNanos = System.nanoTime();
+        succeeded(getNanos(), description);
+    }
+
+    @Override final protected void failed(Throwable e, Description description) {
+        endNanos = System.nanoTime();
+        failed(getNanos(), e, description);
+    }
+
+    @Override final protected void skipped(AssumptionViolatedException e, Description description) {
+        endNanos = System.nanoTime();
+        skipped(getNanos(), e, description);
+    }
+
+    @Override final protected void starting(Description description) {
+        startNanos = System.nanoTime();
+    }
+
+    @Override final protected void finished(Description description) {
+        finished(getNanos(), description);
+    }
+}

src/test/java/org/junit/tests/AllTests.java

@@ -34,6 +34,7 @@
 import org.junit.tests.experimental.rules.TempFolderRuleTest;
 import org.junit.tests.experimental.rules.TemporaryFolderUsageTest;
 import org.junit.tests.experimental.rules.TestRuleTest;
+import org.junit.tests.experimental.rules.TimeWatcherTest;
 import org.junit.tests.experimental.rules.TimeoutRuleTest;
 import org.junit.tests.experimental.rules.VerifierRuleTest;
 import org.junit.tests.experimental.theories.AllMembersSupplierTest;
@@ -160,7 +161,8 @@
         BlockJUnit4ClassRunnerTest.class,
         MethodSorterTest.class,
         TestedOnSupplierTest.class,
-        StacktracePrintingMatcherTest.class
+        StacktracePrintingMatcherTest.class,
+        TimeWatcherTest.class
 })
 public class AllTests {
     public static Test suite() {

src/test/java/org/junit/tests/experimental/rules/TimeWatcherTest.java

@@ -0,0 +1,139 @@
+package org.junit.tests.experimental.rules;
+
+import org.junit.Before;
+import org.junit.Rule;
+import org.junit.Test;
+import org.junit.internal.AssumptionViolatedException;
+import org.junit.rules.TimeWatcher;
+import org.junit.runner.Description;
+import org.junit.runner.JUnitCore;
+import org.junit.runner.Result;
+
+import java.util.logging.Logger;
+
+import static org.hamcrest.core.Is.is;
+import static org.hamcrest.core.IsEqual.equalTo;
+import static org.hamcrest.core.IsNot.not;
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertThat;
+import static org.junit.Assume.assumeTrue;
+import static org.junit.Assert.fail;
+
+/**
+ * @author tibor17
+ * @since 4.12
+ */
+public class TimeWatcherTest {
+    public static enum TestStatus {PASSED, FAILED, SKIPPED }
+
+    public static abstract class AbstractTimeWatcherTest {
+        private static final Logger logger = Logger.getLogger("");
+
+        public static long timeSpent;
+        public static long timeSpentIfFinished;
+        public static String testName;
+        public static String testNameIfFinished;
+        public static TestStatus status;
+
+        private static void logInfo(String name, String status, long nanos) {
+            logger.info(String.format("Test '%s' %s, spent %d microseconds",
+                    name, status, TimeWatcher.toMicros(nanos)));
+        }
+
+        @Rule
+        public final TimeWatcher timeWatcher = new TimeWatcher() {
+            @Override
+            protected void succeeded(long nanos, Description description) {
+                timeSpent = nanos;
+                status = TestStatus.PASSED;
+                testName = description.getMethodName();
+                //logInfo(testName, status.name(), timeSpent);
+            }
+
+            @Override
+            protected void failed(long nanos, Throwable e, Description description) {
+                timeSpent = nanos;
+                status = TestStatus.FAILED;
+                testName = description.getMethodName();
+                //logInfo(testName, status.name(), timeSpent);
+            }
+
+            @Override
+            protected void skipped(long nanos, AssumptionViolatedException e, Description description) {
+                timeSpent = nanos;
+                status = TestStatus.SKIPPED;
+                testName = description.getMethodName();
+                //logInfo(testName, status.name(), timeSpent);
+            }
+
+            @Override
+            protected void finished(long nanos, Description description) {
+                timeSpentIfFinished = nanos;
+                testNameIfFinished = description.getMethodName();
+                //logInfo(testNameIfFinished, "finished", timeSpentIfFinished);
+            }
+        };
+    }
+
+    public static class SuccessfulTest extends AbstractTimeWatcherTest {
+        @Test
+        public void successfulTest() {
+        }
+    }
+
+    public static class FailedTest extends AbstractTimeWatcherTest {
+        @Test
+        public void failedTest() {
+            fail();
+        }
+    }
+
+    public static class SkippedTest extends AbstractTimeWatcherTest {
+        @Test
+        public void skippedTest() {
+            assumeTrue(false);
+        }
+    }
+
+    @Before
+    public void init() {
+        AbstractTimeWatcherTest.testName = null;
+        AbstractTimeWatcherTest.testNameIfFinished = null;
+        AbstractTimeWatcherTest.status = null;
+        AbstractTimeWatcherTest.timeSpent = 0;
+        AbstractTimeWatcherTest.timeSpentIfFinished = 0;
+    }
+
+    @Test
+    public void succeeded() {
+        Result result = JUnitCore.runClasses(SuccessfulTest.class);
+        assertEquals(0, result.getFailureCount());
+        assertThat(AbstractTimeWatcherTest.testName, is(equalTo("successfulTest")));
+        assertThat(AbstractTimeWatcherTest.testName, is(equalTo(AbstractTimeWatcherTest.testNameIfFinished)));
+        assertThat(AbstractTimeWatcherTest.status, is(equalTo(TestStatus.PASSED)));
+        assertThat(AbstractTimeWatcherTest.timeSpent, is(not(0L)));
+        assertThat(AbstractTimeWatcherTest.timeSpent, is(equalTo(AbstractTimeWatcherTest.timeSpentIfFinished)));
+    }
+
+    @Test
+    public void failed() {
+        Result result = JUnitCore.runClasses(FailedTest.class);
+        assertEquals(1, result.getFailureCount());
+        assertThat(AbstractTimeWatcherTest.testName, is(equalTo("failedTest")));
+        assertThat(AbstractTimeWatcherTest.testName, is(equalTo(AbstractTimeWatcherTest.testNameIfFinished)));
+        assertThat(AbstractTimeWatcherTest.status, is(equalTo(TestStatus.FAILED)));
+        assertThat(AbstractTimeWatcherTest.timeSpent, is(not(0L)));
+        assertThat(AbstractTimeWatcherTest.timeSpent, is(equalTo(AbstractTimeWatcherTest.timeSpentIfFinished)));
+    }
+
+    @Test
+    public void skipped() {
+        Result result = JUnitCore.runClasses(SkippedTest.class);
+        assertEquals(0, result.getFailureCount());
+        assertThat(AbstractTimeWatcherTest.testName, is(equalTo("skippedTest")));
+        assertThat(AbstractTimeWatcherTest.testName, is(equalTo(AbstractTimeWatcherTest.testNameIfFinished)));
+        assertThat(AbstractTimeWatcherTest.status, is(equalTo(TestStatus.SKIPPED)));
+        assertThat(AbstractTimeWatcherTest.timeSpent, is(not(0L)));
+        assertThat(AbstractTimeWatcherTest.timeSpent, is(equalTo(AbstractTimeWatcherTest.timeSpentIfFinished)));
+    }
+}