Use System.nanoTime() in StopWatch

Prior to this commit, StopWatch used System.currentTimeMillis() to
track and report running time in milliseconds.

This commit updates the internals of StopWatch to use System.nanoTime()
instead of System.currentTimeMillis(). Consequently, running time is
now tracked and reported in nanoseconds; however, users still have the
option to retrieve running time in milliseconds or seconds.

Closes gh-23235

spring-core/src/main/java/org/springframework/util/StopWatch.java

@@ -1,5 +1,5 @@
 /*
- * Copyright 2002-2018 the original author or authors.
+ * Copyright 2002-2019 the original author or authors.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -19,21 +19,25 @@ package org.springframework.util;
 import java.text.NumberFormat;
 import java.util.LinkedList;
 import java.util.List;
+import java.util.concurrent.TimeUnit;
 
 import org.springframework.lang.Nullable;
 
 /**
- * Simple stop watch, allowing for timing of a number of tasks,
+ * Simple stop watch, allowing for timing of a number of tasks, exposing total
- * exposing total running time and running time for each named task.
+ * running time and running time for each named task.
  *
- * <p>Conceals use of {@code System.currentTimeMillis()}, improving the
+ * <p>Conceals use of {@link System#nanoTime()}, improving the readability of
- * readability of application code and reducing the likelihood of calculation errors.
+ * application code and reducing the likelihood of calculation errors.
  *
- * <p>Note that this object is not designed to be thread-safe and does not
+ * <p>Note that this object is not designed to be thread-safe and does not use
- * use synchronization.
+ * synchronization.
  *
- * <p>This class is normally used to verify performance during proof-of-concepts
+ * <p>This class is normally used to verify performance during proof-of-concept
- * and in development, rather than as part of production applications.
+ * work and in development, rather than as part of production applications.
+ *
+ * <p>As of Spring Framework 5.2, running time is tracked and reported in
+ * nanoseconds.
  *
  * @author Rod Johnson
  * @author Juergen Hoeller
@@ -43,9 +47,9 @@ import org.springframework.lang.Nullable;
 public class StopWatch {
 
 	/**
-	 * Identifier of this stop watch.
+	 * Identifier of this {@code StopWatch}.
-	 * Handy when we have output from multiple stop watches
+	 * <p>Handy when we have output from multiple stop watches and need to
-	 * and need to distinguish between them in log or console output.
+	 * distinguish between them in log or console output.
 	 */
 	private final String id;
 
@@ -54,7 +58,7 @@ public class StopWatch {
 	private final List<TaskInfo> taskList = new LinkedList<>();
 
 	/** Start time of the current task. */
-	private long startTimeMillis;
+	private long startTimeNanos;
 
 	/** Name of the current task. */
 	@Nullable
@@ -66,22 +70,23 @@ public class StopWatch {
 	private int taskCount;
 
 	/** Total running time. */
-	private long totalTimeMillis;
+	private long totalTimeNanos;
 
 
 	/**
-	 * Construct a new stop watch. Does not start any task.
+	 * Construct a new {@code StopWatch}.
+	 * <p>Does not start any task.
 	 */
 	public StopWatch() {
 		this("");
 	}
 
 	/**
-	 * Construct a new stop watch with the given id.
+	 * Construct a new {@code StopWatch} with the given ID.
-	 * Does not start any task.
+	 * <p>The ID is handy when we have output from multiple stop watches and need
-	 * @param id identifier for this stop watch.
+	 * to distinguish between them.
-	 * Handy when we have output from multiple stop watches
+	 * <p>Does not start any task.
-	 * and need to distinguish between them.
+	 * @param id identifier for this stop watch
 	 */
 	public StopWatch(String id) {
 		this.id = id;
@@ -89,8 +94,8 @@ public class StopWatch {
 
 
 	/**
-	 * Return the id of this stop watch, as specified on construction.
+	 * Get the ID of this {@code StopWatch}, as specified on construction.
-	 * @return the id (empty String by default)
+	 * @return the ID (empty String by default)
 	 * @since 4.2.2
 	 * @see #StopWatch(String)
 	 */
@@ -99,9 +104,11 @@ public class StopWatch {
 	}
 
 	/**
-	 * Determine whether the TaskInfo array is built over time. Set this to
+	 * Configure whether the {@link TaskInfo} array is built over time.
-	 * "false" when using a StopWatch for millions of intervals, or the task
+	 * <p>Set this to {@code false} when using a {@code StopWatch} for millions
-	 * info structure will consume excessive memory. Default is "true".
+	 * of intervals; otherwise, the {@code TaskInfo} structure will consume
+	 * excessive memory.
+	 * <p>Default is {@code true}.
 	 */
 	public void setKeepTaskList(boolean keepTaskList) {
 		this.keepTaskList = keepTaskList;
@@ -109,8 +116,10 @@ public class StopWatch {
 
 
 	/**
-	 * Start an unnamed task. The results are undefined if {@link #stop()}
+	 * Start an unnamed task.
-	 * or timing methods are called without invoking this method.
+	 * <p>The results are undefined if {@link #stop()} or timing methods are
+	 * called without invoking this method first.
+	 * @see #start(String)
 	 * @see #stop()
 	 */
 	public void start() throws IllegalStateException {
@@ -118,9 +127,11 @@ public class StopWatch {
 	}
 
 	/**
-	 * Start a named task. The results are undefined if {@link #stop()}
+	 * Start a named task.
-	 * or timing methods are called without invoking this method.
+	 * <p>The results are undefined if {@link #stop()} or timing methods are
+	 * called without invoking this method first.
 	 * @param taskName the name of the task to start
+	 * @see #start()
 	 * @see #stop()
 	 */
 	public void start(String taskName) throws IllegalStateException {
@@ -128,21 +139,22 @@ public class StopWatch {
 			throw new IllegalStateException("Can't start StopWatch: it's already running");
 		}
 		this.currentTaskName = taskName;
-		this.startTimeMillis = System.currentTimeMillis();
+		this.startTimeNanos = System.nanoTime();
 	}
 
 	/**
-	 * Stop the current task. The results are undefined if timing
+	 * Stop the current task.
-	 * methods are called without invoking at least one pair
+	 * <p>The results are undefined if timing methods are called without invoking
-	 * {@code start()} / {@code stop()} methods.
+	 * at least one pair of {@code start()} / {@code stop()} methods.
 	 * @see #start()
+	 * @see #start(String)
 	 */
 	public void stop() throws IllegalStateException {
 		if (this.currentTaskName == null) {
 			throw new IllegalStateException("Can't stop StopWatch: it's not running");
 		}
-		long lastTime = System.currentTimeMillis() - this.startTimeMillis;
+		long lastTime = System.nanoTime() - this.startTimeNanos;
-		this.totalTimeMillis += lastTime;
+		this.totalTimeNanos += lastTime;
 		this.lastTaskInfo = new TaskInfo(this.currentTaskName, lastTime);
 		if (this.keepTaskList) {
 			this.taskList.add(this.lastTaskInfo);
@@ -152,7 +164,7 @@ public class StopWatch {
 	}
 
 	/**
-	 * Return whether the stop watch is currently running.
+	 * Determine whether this {@code StopWatch} is currently running.
 	 * @see #currentTaskName()
 	 */
 	public boolean isRunning() {
@@ -160,7 +172,7 @@ public class StopWatch {
 	}
 
 	/**
-	 * Return the name of the currently running task, if any.
+	 * Get the name of the currently running task, if any.
 	 * @since 4.2.2
 	 * @see #isRunning()
 	 */
@@ -169,9 +181,21 @@ public class StopWatch {
 		return this.currentTaskName;
 	}
 
+	/**
+	 * Get the time taken by the last task in nanoseconds.
+	 * @since 5.2
+	 * @see #getLastTaskTimeMillis()
+	 */
+	public long getLastTaskTimeNanos() throws IllegalStateException {
+		if (this.lastTaskInfo == null) {
+			throw new IllegalStateException("No tasks run: can't get last task interval");
+		}
+		return this.lastTaskInfo.getTimeNanos();
+	}
 
 	/**
-	 * Return the time taken by the last task.
+	 * Get the time taken by the last task in milliseconds.
+	 * @see #getLastTaskTimeNanos()
 	 */
 	public long getLastTaskTimeMillis() throws IllegalStateException {
 		if (this.lastTaskInfo == null) {
@@ -181,7 +205,7 @@ public class StopWatch {
 	}
 
 	/**
-	 * Return the name of the last task.
+	 * Get the name of the last task.
 	 */
 	public String getLastTaskName() throws IllegalStateException {
 		if (this.lastTaskInfo == null) {
@@ -191,7 +215,7 @@ public class StopWatch {
 	}
 
 	/**
-	 * Return the last task as a TaskInfo object.
+	 * Get the last task as a {@link TaskInfo} object.
 	 */
 	public TaskInfo getLastTaskInfo() throws IllegalStateException {
 		if (this.lastTaskInfo == null) {
@@ -202,28 +226,42 @@ public class StopWatch {
 
 
 	/**
-	 * Return the total time in milliseconds for all tasks.
+	 * Get the total time in nanoseconds for all tasks.
+	 * @since 5.2
+	 * @see #getTotalTimeMillis()
+	 * @see #getTotalTimeSeconds()
+	 */
+	public long getTotalTimeNanos() {
+		return this.totalTimeNanos;
+	}
+
+	/**
+	 * Get the total time in milliseconds for all tasks.
+	 * @see #getTotalTimeNanos()
+	 * @see #getTotalTimeSeconds()
 	 */
 	public long getTotalTimeMillis() {
-		return this.totalTimeMillis;
+		return nanosToMillis(this.totalTimeNanos);
 	}
 
 	/**
-	 * Return the total time in seconds for all tasks.
+	 * Get the total time in seconds for all tasks.
+	 * @see #getTotalTimeNanos()
+	 * @see #getTotalTimeMillis()
 	 */
 	public double getTotalTimeSeconds() {
-		return this.totalTimeMillis / 1000.0;
+		return nanosToSeconds(this.totalTimeNanos);
 	}
 
 	/**
-	 * Return the number of tasks timed.
+	 * Get the number of tasks timed.
 	 */
 	public int getTaskCount() {
 		return this.taskCount;
 	}
 
 	/**
-	 * Return an array of the data for tasks performed.
+	 * Get an array of the data for tasks performed.
 	 */
 	public TaskInfo[] getTaskInfo() {
 		if (!this.keepTaskList) {
@@ -234,15 +272,16 @@ public class StopWatch {
 
 
 	/**
-	 * Return a short description of the total running time.
+	 * Get a short description of the total running time.
 	 */
 	public String shortSummary() {
-		return "StopWatch '" + getId() + "': running time (millis) = " + getTotalTimeMillis();
+		return "StopWatch '" + getId() + "': running time = " + getTotalTimeNanos() + " ns";
 	}
 
 	/**
-	 * Return a string with a table describing all tasks performed.
+	 * Generate a string with a table describing all tasks performed.
-	 * For custom reporting, call getTaskInfo() and use the task info directly.
+	 * <p>For custom reporting, call {@link #getTaskInfo()} and use the task info
+	 * directly.
 	 */
 	public String prettyPrint() {
 		StringBuilder sb = new StringBuilder(shortSummary());
@@ -251,18 +290,18 @@ public class StopWatch {
 			sb.append("No task info kept");
 		}
 		else {
-			sb.append("-----------------------------------------\n");
+			sb.append("---------------------------------------------\n");
-			sb.append("ms     %     Task name\n");
+			sb.append("ns         %     Task name\n");
-			sb.append("-----------------------------------------\n");
+			sb.append("---------------------------------------------\n");
 			NumberFormat nf = NumberFormat.getNumberInstance();
-			nf.setMinimumIntegerDigits(5);
+			nf.setMinimumIntegerDigits(9);
 			nf.setGroupingUsed(false);
 			NumberFormat pf = NumberFormat.getPercentInstance();
 			pf.setMinimumIntegerDigits(3);
 			pf.setGroupingUsed(false);
 			for (TaskInfo task : getTaskInfo()) {
-				sb.append(nf.format(task.getTimeMillis())).append("  ");
+				sb.append(nf.format(task.getTimeNanos())).append("  ");
-				sb.append(pf.format(task.getTimeSeconds() / getTotalTimeSeconds())).append("  ");
+				sb.append(pf.format((double) task.getTimeNanos() / getTotalTimeNanos())).append("  ");
 				sb.append(task.getTaskName()).append("\n");
 			}
 		}
@@ -270,16 +309,17 @@ public class StopWatch {
 	}
 
 	/**
-	 * Return an informative string describing all tasks performed
+	 * Generate an informative string describing all tasks performed
-	 * For custom reporting, call {@code getTaskInfo()} and use the task info directly.
+	 * <p>For custom reporting, call {@link #getTaskInfo()} and use the task info
+	 * directly.
 	 */
 	@Override
 	public String toString() {
 		StringBuilder sb = new StringBuilder(shortSummary());
 		if (this.keepTaskList) {
 			for (TaskInfo task : getTaskInfo()) {
-				sb.append("; [").append(task.getTaskName()).append("] took ").append(task.getTimeMillis());
+				sb.append("; [").append(task.getTaskName()).append("] took ").append(task.getTimeNanos()).append(" ns");
-				long percent = Math.round((100.0 * task.getTimeSeconds()) / getTotalTimeSeconds());
+				long percent = Math.round(100.0 * task.getTimeNanos() / getTotalTimeNanos());
 				sb.append(" = ").append(percent).append("%");
 			}
 		}
@@ -290,40 +330,64 @@ public class StopWatch {
 	}
 
 
+	private static long nanosToMillis(long duration) {
+		return TimeUnit.NANOSECONDS.toMillis(duration);
+	}
+
+	private static double nanosToSeconds(long duration) {
+		return duration / 1_000_000_000.0;
+	}
+
+
 	/**
-	 * Inner class to hold data about one task executed within the stop watch.
+	 * Nested class to hold data about one task executed within the {@code StopWatch}.
 	 */
 	public static final class TaskInfo {
 
 		private final String taskName;
 
-		private final long timeMillis;
+		private final long timeNanos;
 
-		TaskInfo(String taskName, long timeMillis) {
+		TaskInfo(String taskName, long timeNanos) {
 			this.taskName = taskName;
-			this.timeMillis = timeMillis;
+			this.timeNanos = timeNanos;
 		}
 
 		/**
-		 * Return the name of this task.
+		 * Get the name of this task.
 		 */
 		public String getTaskName() {
 			return this.taskName;
 		}
 
 		/**
-		 * Return the time in milliseconds this task took.
+		 * Get the time in nanoseconds this task took.
+		 * @since 5.2
+		 * @see #getTimeMillis()
+		 * @see #getTimeSeconds()
 		 */
-		public long getTimeMillis() {
+		public long getTimeNanos() {
-			return this.timeMillis;
+			return this.timeNanos;
 		}
 
 		/**
-		 * Return the time in seconds this task took.
+		 * Get the time in milliseconds this task took.
+		 * @see #getTimeNanos()
+		 * @see #getTimeSeconds()
+		 */
+		public long getTimeMillis() {
+			return nanosToMillis(this.timeNanos);
+		}
+
+		/**
+		 * Get the time in seconds this task took.
+		 * @see #getTimeMillis()
+		 * @see #getTimeNanos()
 		 */
 		public double getTimeSeconds() {
-			return (this.timeMillis / 1000.0);
+			return nanosToSeconds(this.timeNanos);
 		}
+
 	}
 
 }

spring-core/src/test/java/org/springframework/util/StopWatchTests.java

@@ -16,6 +16,8 @@
 
 package org.springframework.util;
 
+import java.util.concurrent.TimeUnit;
+
 import org.junit.Test;
 
 import org.springframework.util.StopWatch.TaskInfo;
@@ -39,8 +41,8 @@ public class StopWatchTests {
 	private static final String name2 = "Task 2";
 
 	private static final long duration1 = 200;
-	private static final long duration2 = 50;
+	private static final long duration2 = 100;
-	private static final long fudgeFactor = 20;
+	private static final long fudgeFactor = 50;
 
 	private final StopWatch stopWatch = new StopWatch(ID);
 
@@ -70,30 +72,44 @@ public class StopWatchTests {
 	@Test
 	public void validUsage() throws Exception {
 		assertThat(stopWatch.isRunning()).isFalse();
+
 		stopWatch.start(name1);
 		Thread.sleep(duration1);
 		assertThat(stopWatch.isRunning()).isTrue();
 		assertThat(stopWatch.currentTaskName()).isEqualTo(name1);
 		stopWatch.stop();
 		assertThat(stopWatch.isRunning()).isFalse();
-
+		assertThat(stopWatch.getLastTaskTimeNanos())
+			.as("last task time in nanoseconds for task #1")
+			.isGreaterThanOrEqualTo(millisToNanos(duration1))
+			.isLessThanOrEqualTo(millisToNanos(duration1 + fudgeFactor));
 		assertThat(stopWatch.getTotalTimeMillis())
-			.as("Unexpected timing " + stopWatch.getTotalTimeMillis())
+			.as("total time in milliseconds for task #1")
-			.isGreaterThanOrEqualTo(duration1);
+			.isGreaterThanOrEqualTo(duration1)
-		assertThat(stopWatch.getTotalTimeMillis())
-			.as("Unexpected timing " + stopWatch.getTotalTimeMillis())
 			.isLessThanOrEqualTo(duration1 + fudgeFactor);
+		assertThat(stopWatch.getTotalTimeSeconds())
+			.as("total time in seconds for task #1")
+			.isGreaterThanOrEqualTo(duration1 / 1000.0)
+			.isLessThanOrEqualTo((duration1 + fudgeFactor) / 1000.0);
 
 		stopWatch.start(name2);
 		Thread.sleep(duration2);
+		assertThat(stopWatch.isRunning()).isTrue();
+		assertThat(stopWatch.currentTaskName()).isEqualTo(name2);
 		stopWatch.stop();
-
+		assertThat(stopWatch.isRunning()).isFalse();
+		assertThat(stopWatch.getLastTaskTimeNanos())
+			.as("last task time in nanoseconds for task #2")
+			.isGreaterThanOrEqualTo(millisToNanos(duration2))
+			.isLessThanOrEqualTo(millisToNanos(duration2 + fudgeFactor));
 		assertThat(stopWatch.getTotalTimeMillis())
-			.as("Unexpected timing " + stopWatch.getTotalTimeMillis())
+			.as("total time in milliseconds for tasks #1 and #2")
-			.isGreaterThanOrEqualTo(duration1 + duration2);
+			.isGreaterThanOrEqualTo(duration1 + duration2)
-		assertThat(stopWatch.getTotalTimeMillis())
-			.as("Unexpected timing " + stopWatch.getTotalTimeMillis())
 			.isLessThanOrEqualTo(duration1 + duration2 + fudgeFactor);
+		assertThat(stopWatch.getTotalTimeSeconds())
+			.as("total time in seconds for task #2")
+			.isGreaterThanOrEqualTo((duration1 + duration2) / 1000.0)
+			.isLessThanOrEqualTo((duration1 + duration2 + fudgeFactor) / 1000.0);
 
 		assertThat(stopWatch.getTaskCount()).isEqualTo(2);
 		assertThat(stopWatch.prettyPrint()).contains(name1, name2);
@@ -106,24 +122,26 @@ public class StopWatchTests {
 	public void validUsageDoesNotKeepTaskList() throws Exception {
 		stopWatch.setKeepTaskList(false);
 
-		assertThat(stopWatch.isRunning()).isFalse();
-
 		stopWatch.start(name1);
 		Thread.sleep(duration1);
-		assertThat(stopWatch.isRunning()).isTrue();
+		assertThat(stopWatch.currentTaskName()).isEqualTo(name1);
 		stopWatch.stop();
-		assertThat(stopWatch.isRunning()).isFalse();
 
 		stopWatch.start(name2);
 		Thread.sleep(duration2);
-		assertThat(stopWatch.isRunning()).isTrue();
+		assertThat(stopWatch.currentTaskName()).isEqualTo(name2);
 		stopWatch.stop();
-		assertThat(stopWatch.isRunning()).isFalse();
 
 		assertThat(stopWatch.getTaskCount()).isEqualTo(2);
 		assertThat(stopWatch.prettyPrint()).contains("No task info kept");
 		assertThat(stopWatch.toString()).doesNotContain(name1, name2);
-		assertThatExceptionOfType(UnsupportedOperationException.class).isThrownBy(stopWatch::getTaskInfo);
+		assertThatExceptionOfType(UnsupportedOperationException.class)
+			.isThrownBy(stopWatch::getTaskInfo)
+			.withMessage("Task info is not being kept!");
+	}
+
+	private static long millisToNanos(long duration) {
+		return TimeUnit.NANOSECONDS.convert(duration, TimeUnit.MILLISECONDS);
 	}
 
 }