Merge pull request #1199 from Vampire/nanoTime

Replace currentTimeMillis() with nanoTime() for duration measuring

pitest-entry/src/main/java/org/pitest/coverage/execute/DefaultCoverageGenerator.java

@@ -49,6 +49,8 @@
 import java.util.logging.Logger;
 import java.util.stream.Collectors;
 
+import static java.util.concurrent.TimeUnit.NANOSECONDS;
+
 public class DefaultCoverageGenerator implements CoverageGenerator {
 
   private static final Logger    LOG = Log.getLogger();
@@ -77,7 +79,7 @@ public DefaultCoverageGenerator(final File workingDir,
   @Override
   public CoverageData calculateCoverage() {
     try {
-      final long t0 = System.currentTimeMillis();
+      final long t0 = System.nanoTime();
 
       this.timings.registerStart(Timings.Stage.SCAN_CLASS_PATH);
       List<String> tests = this.code.testTrees()
@@ -94,7 +96,7 @@ public CoverageData calculateCoverage() {
       gatherCoverageData(tests, coverage);
       this.timings.registerEnd(Timings.Stage.COVERAGE);
 
-      final long time = (System.currentTimeMillis() - t0) / 1000;
+      final long time = NANOSECONDS.toSeconds(System.nanoTime() - t0);
 
       LOG.info("Calculated coverage in " + time + " seconds.");
 

pitest-entry/src/main/java/org/pitest/mutationtest/tooling/MutationCoverage.java

@@ -78,6 +78,7 @@
 
 import static java.util.Collections.emptyList;
 import static java.util.Collections.emptySet;
+import static java.util.concurrent.TimeUnit.NANOSECONDS;
 
 public class MutationCoverage {
 
@@ -118,7 +119,7 @@ public CombinedStatistics runReport() throws IOException {
     LOG.fine("Maximum available memory is " + (runtime.maxMemory() / MB)
         + " mb");
 
-    final long t0 = System.currentTimeMillis();
+    final long t0 = System.nanoTime();
 
     List<String> issues = verifyBuildSuitableForMutationTesting();
 
@@ -270,7 +271,7 @@ private List<MutationResultListener> createConfig(long t0,
     final ListenerArguments args = new ListenerArguments(
         this.strategies.output(), coverageData, new SmartSourceLocator(
             data.getSourcePaths(), this.data.getInputEncoding()), engine, t0, this.data.isFullMutationMatrix(), data);
-    
+
     final MutationResultListener mutationReportListener = this.strategies
         .listenerFactory().getListener(this.data.getFreeFormProperties(), args);
 
@@ -398,7 +399,7 @@ private void checkMutationsFound(final List<MutationAnalysisUnit> tus) {
   }
 
   private String timeSpan(final long t0) {
-    return "" + ((System.currentTimeMillis() - t0) / 1000) + " seconds";
+    return "" + (NANOSECONDS.toSeconds(System.nanoTime() - t0)) + " seconds";
   }
 
   private CoverageGenerator coverage() {

pitest-entry/src/main/java/org/pitest/util/TimeSpan.java

@@ -14,6 +14,9 @@
  */
 package org.pitest.util;
 
+import static java.util.concurrent.TimeUnit.MILLISECONDS;
+import static java.util.concurrent.TimeUnit.NANOSECONDS;
+
 public class TimeSpan {
 
   private long start;
@@ -25,7 +28,7 @@ public TimeSpan(final long start, final long end) {
   }
 
   public long duration() {
-    return this.end - this.start;
+    return NANOSECONDS.toMillis(this.end - this.start);
   }
 
   public long getStart() {
@@ -47,9 +50,9 @@ public void setEnd(final long end) {
   @Override
   public String toString() {
     final long millis = duration();
-    final int seconds = (int) (millis / 1000) % 60;
-    final int minutes = (int) ((millis / (1000 * 60)) % 60);
-    final int hours = (int) ((millis / (1000 * 60 * 60)) % 24);
+    final int seconds = (int) (MILLISECONDS.toSeconds(millis) % 60);
+    final int minutes = (int) (MILLISECONDS.toMinutes(millis) % 60);
+    final int hours = (int) MILLISECONDS.toHours(millis);
 
     if (hours != 0) {
       return "" + hours + " hours, " + minutes + " minutes and " + seconds

pitest-entry/src/main/java/org/pitest/util/Timings.java

@@ -19,6 +19,8 @@
 import java.util.Map;
 import java.util.Map.Entry;
 
+import static java.util.concurrent.TimeUnit.MILLISECONDS;
+
 public class Timings {
 
   public enum Stage {
@@ -43,11 +45,11 @@ public String toString() {
   private final Map<Stage, TimeSpan> timings = new LinkedHashMap<>();
 
   public void registerStart(final Stage stage) {
-    this.timings.put(stage, new TimeSpan(System.currentTimeMillis(), 0));
+    this.timings.put(stage, new TimeSpan(System.nanoTime(), 0));
   }
 
   public void registerEnd(final Stage stage) {
-    final long end = System.currentTimeMillis();
+    final long end = System.nanoTime();
     this.timings.get(stage).setEnd(end);
   }
 
@@ -58,7 +60,7 @@ public void report(final PrintStream ps) {
       ps.println("> " + each.getKey() + " : " + each.getValue());
     }
     ps.println(StringUtil.separatorLine());
-    ps.println("> Total " + " : " + new TimeSpan(0, total));
+    ps.println("> Total " + " : " + new TimeSpan(0, MILLISECONDS.toNanos(total)));
     ps.println(StringUtil.separatorLine());
   }
 

pitest-entry/src/test/java/org/pitest/util/TimeSpanTest.java

@@ -14,6 +14,10 @@
  */
 package org.pitest.util;
 
+import static java.util.concurrent.TimeUnit.HOURS;
+import static java.util.concurrent.TimeUnit.MILLISECONDS;
+import static java.util.concurrent.TimeUnit.MINUTES;
+import static java.util.concurrent.TimeUnit.SECONDS;
 import static org.junit.Assert.assertEquals;
 
 import org.junit.Test;
@@ -22,23 +26,23 @@ public class TimeSpanTest {
 
   @Test
   public void shouldReportTimesAsLessThanOneSecondWhenLessThanOneSecond() {
-    assertEquals("< 1 second", new TimeSpan(0, 999).toString());
+    assertEquals("< 1 second", new TimeSpan(0, MILLISECONDS.toNanos(999)).toString());
   }
 
   @Test
   public void shouldReportTimesInSecondsWhenLessThenOneMinute() {
-    assertEquals("59 seconds", new TimeSpan(0, 59 * 1000).toString());
+    assertEquals("59 seconds", new TimeSpan(0, SECONDS.toNanos(59)).toString());
   }
 
   @Test
   public void shouldReportTimesInMinutesWhenMoreThanOneMinute() {
     assertEquals("1 minutes and 1 seconds",
-        new TimeSpan(0, (61 * 1000)).toString());
+        new TimeSpan(0, MINUTES.toNanos(1) + SECONDS.toNanos(1)).toString());
   }
 
   @Test
   public void shouldReportTimesInHoursWhenMoreThanOneHour() {
     assertEquals("1 hours, 2 minutes and 1 seconds", new TimeSpan(0,
-        (1000 * 60 * 60) + (121 * 1000)).toString());
+        HOURS.toNanos(1) + MINUTES.toNanos(2) + SECONDS.toNanos(1)).toString());
   }
 }

pitest-maven-verification/src/test/java/org/pitest/PitMojoIT.java

@@ -35,6 +35,7 @@
 import java.util.Properties;
 
 import static java.util.Arrays.asList;
+import static java.util.concurrent.TimeUnit.NANOSECONDS;
 import static org.assertj.core.api.Assertions.assertThat;
 import static org.junit.Assert.*;
 import static org.junit.Assume.assumeFalse;
@@ -59,13 +60,13 @@ public class PitMojoIT {
   @Before
   public void beforeEachTest() {
     LOGGER.info("running test '{}' with {} ", testName.getMethodName(), VERSION);
-    startTime = System.currentTimeMillis();
+    startTime = System.nanoTime();
   }
 
   @After
   public void afterEachTest() {
     LOGGER.info("duration of test '{}' {}ms", testName.getMethodName(),
-        System.currentTimeMillis() - startTime);
+        NANOSECONDS.toMillis(System.nanoTime() - startTime));
   }
 
   @Test

pitest/src/main/java/org/pitest/coverage/execute/CoverageDecorator.java

@@ -25,6 +25,8 @@
 import org.pitest.testapi.execute.ExitingResultCollector;
 import org.pitest.util.Log;
 
+import static java.util.concurrent.TimeUnit.NANOSECONDS;
+
 public class CoverageDecorator extends TestUnitDecorator {
 
   private static final Logger    LOG     = Log.getLogger();
@@ -43,12 +45,12 @@ public void execute(final ResultCollector rc) {
 
     final int threadsBeforeTest = this.threads.getThreadCount();
 
-    final long t0 = System.currentTimeMillis();
+    final long t0 = System.nanoTime();
     final ExitingResultCollector wrappedCollector = new ExitingResultCollector(
         rc);
     this.child().execute(wrappedCollector);
 
-    final int executionTime = (int) (System.currentTimeMillis() - t0);
+    final int executionTime = (int) NANOSECONDS.toMillis(System.nanoTime() - t0);
 
     final int threadsAfterTest = this.threads.getThreadCount();
     if (threadsAfterTest > threadsBeforeTest) {

pitest/src/main/java/org/pitest/coverage/execute/CoverageTestExecutionListener.java

@@ -9,6 +9,8 @@
 import java.lang.management.ThreadMXBean;
 import java.util.logging.Logger;
 
+import static java.util.concurrent.TimeUnit.NANOSECONDS;
+
 public class CoverageTestExecutionListener implements TestUnitExecutionListener {
 
     private static final Logger LOG = Log.getLogger();
@@ -25,13 +27,13 @@ public CoverageTestExecutionListener(CoverageReceiver invokeQueue) {
     @Override
     public void executionStarted(Description description) {
         LOG.fine(() -> "Gathering coverage for test " + description);
-        t0 = System.currentTimeMillis();
+        t0 = System.nanoTime();
         threadsBeforeTest = this.threads.getThreadCount();
     }
 
     @Override
     public void executionFinished(Description description, boolean passed) {
-        int executionTime = (int) (System.currentTimeMillis() - t0);
+        int executionTime = (int) NANOSECONDS.toMillis(System.nanoTime() - t0);
         if (executionTime < 0) {
             LOG.warning("Recorded negative test time. Test life cycle not as expected.");
             // substitute an unimportant, but high, time for this test so it is unlikely to

pitest/src/main/java/org/pitest/mutationtest/execute/MutationTestWorker.java

@@ -42,6 +42,7 @@
 import java.util.logging.Logger;
 import java.util.stream.Collectors;
 
+import static java.util.concurrent.TimeUnit.NANOSECONDS;
 import static org.pitest.util.Unchecked.translateCheckedException;
 
 public class MutationTestWorker {
@@ -79,10 +80,10 @@ protected void run(final Collection<MutationDetails> range, final Reporter r,
       if (DEBUG) {
         LOG.fine("Running mutation " + mutation);
       }
-      final long t0 = System.currentTimeMillis();
+      final long t0 = System.nanoTime();
       processMutation(r, testSource, mutation);
       if (DEBUG) {
-        LOG.fine("processed mutation in " + (System.currentTimeMillis() - t0)
+        LOG.fine("processed mutation in " + NANOSECONDS.toMillis(System.nanoTime() - t0)
             + " ms.");
       }
     }
@@ -145,13 +146,13 @@ private MutationStatusTestPair handleCoveredMutation(
     }
 
     final Container c = createNewContainer();
-    final long t0 = System.currentTimeMillis();
+    final long t0 = System.nanoTime();
 
     if (this.hotswap.insertClass(mutationId.getClassName(), this.loader,
         mutatedClass.getBytes())) {
       if (DEBUG) {
         LOG.fine("replaced class with mutant in "
-            + (System.currentTimeMillis() - t0) + " ms");
+            + NANOSECONDS.toMillis(System.nanoTime() - t0) + " ms");
       }
 
       mutationDetected = doTestsDetectMutation(c, relevantTests);
@@ -190,7 +191,7 @@ private MutationStatusTestPair doTestsDetectMutation(final Container c,
       final CheckTestHasFailedResultListener listener = new CheckTestHasFailedResultListener(fullMutationMatrix);
 
       final Pitest pit = new Pitest(listener);
-      
+
       if (this.fullMutationMatrix) {
         pit.run(c, tests);
       } else {