StopWatch使用详解

小奥2024-01-142024-01-15

StopWatch使用详解

当我们需要测试代码性能的时候，你是否第一时间快速的敲出如下代码：

long start = System.currentTimeMillis();
      test();
      long end = System.currentTimeMillis();
      System.out.println("程序执行耗时：" + (end - start));

这样的写法其实并不会有很大的问题，只是当我们需要测试的方法比较多，或者说交叉测试时，就会比较麻烦了。比如：

long start = System.currentTimeMillis();
      test();
      long end = System.currentTimeMillis();
      long start1 = System.currentTimeMillis();
      test1();
      long end1 = System.currentTimeMillis();
      test2();
      long end2 = System.currentTimeMillis();
      System.out.println("test执行耗时：" + (end - start));
      System.out.println("test1执行耗时：" + (end1 - start1));
      System.out.println("test test1 test2执行耗时：" + (end - start));

这样的代码看起来不仅繁琐，而且可读性很差。

所以我今天为大家介绍一个比较好用的计时工具StopWatch，下面让我们一起学习，一起早日用起来吧！

一、认识StopWatch

stopWatch是org.springframework.util包下的一个工具类，使用它可直观的输出代码执行耗时，以及执行时间百分比。

我们可以从源码注释上看到这个工具类的介绍：

Simple stop watch, allowing for timing of a number of tasks, exposing total running time and running time for each named task.
Conceals use of System.nanoTime(), improving the readability of application code and reducing the likelihood of calculation errors.
Note that this object is not designed to be thread-safe and does not use synchronization.
This class is normally used to verify performance during proof-of-concept work and in development, rather than as part of production applications.
As of Spring Framework 5.2, running time is tracked and reported in nanoseconds. As of 6.1, the default time unit for String renderings is seconds with decimal points in nanosecond precision. Custom renderings with specific time units can be requested through prettyPrint(TimeUnit).

简单的秒表，允许对多个任务进行计时，显示总运行时间和每个指定任务的运行时间。
隐藏System.nanoTime()的使用，提高应用程序代码的可读性，减少计算错误的可能性。
注意，这个对象不是被设计为线程安全的，也不使用同步。
该类通常用于在概念验证工作和开发过程中验证性能，而不是作为生产应用程序的一部分。
从Spring Framework 5.2开始，以纳秒为单位跟踪和报告运行时间。从6.1开始，字符串呈现的默认时间单位是秒，其小数点的精度为纳秒。具有特定时间单位的自定义渲染可以通过prettyPrint(TimeUnit)请求。

这里有两点是需要我们注意的：

隐藏System.nanoTime()的使用，提高应用程序代码的可读性，减少计算错误的可能性。
对象不是被设计为线程安全的，也不使用同步。

下面我们来介绍一个这个工具的使用，以及会出现的线程安全问题，并且如何去解决该问题。

1.1 单个任务测试

我们可以调用start()和stop()方法来开始和结束计时，并且通过getTotalTimeMillis()来获取程序执行耗时。

public static void main(String[] args) {
    StopWatch stopWatch = new StopWatch();
    stopWatch.start();
    try {
        // 这里使用线程休眠来模拟耗时程序
        Thread.sleep(1000);
    } catch (Exception e) {
        throw new RuntimeException(e);
    }
    stopWatch.stop();
    System.out.println("程序执行耗时：" + stopWatch.getTotalTimeMillis());
}

控制台输出结果如下：

程序执行耗时：1005

可以看到，这和我们使用System.currentTimeMillis()是一样的，那么有小伙伴就要说了，这和直接使用System.currentTimeMillis()有什么区别吗？先别着急，让我们继续往下看。

1.2 多任务测试并生成统计表

下面我们来看多任务测试，并且调用``生成统计图表的测试代码：

public static void main(String[] args) throws InterruptedException{
       StopWatch stopWatch = new StopWatch("test");
       stopWatch.start("task1");
       Thread.sleep(1000); // 这里使用线程休眠来模拟耗时程序
       stopWatch.stop();
       stopWatch.start("task2");
       Thread.sleep(2000); // 这里使用线程休眠来模拟耗时程序
       stopWatch.stop();
       System.out.println("-------------------");
       System.out.println(stopWatch.prettyPrint());
   }

控制台输出如下：

StopWatch 'test': 3.0113144 seconds
----------------------------------------
Seconds       %       Task name
----------------------------------------
1.0051963     33%     task1
2.0061181     67%     task2

可以看到，不仅编写的代码可读性增强了，而且控制台输出结果也图表化了，更加的直观具体了。

并且我们也可以给不同的StopWatch进行命名，给不同的task命名以便区分不同程序的执行结果测试。

1.3 优缺点

优点

Spring自带工具类，无需三方引入，开箱即用
使用简单，方便
结果格式化输出，展示每项任务耗时与占用时间百分比，结果更加直观
可自定义任务名称，方便查看结果

缺点

一个StopWatch实例一次只能开启一个task，并且需要等stop之后才能start新的task。
代码侵入式使用

注意：单线程使用！！！

StopWatch的源码注释中有明确提到：

注意，这个对象不是被设计为线程安全的，也不使用同步。
该类通常用于在概念验证工作和开发过程中验证性能，而不是作为生产应用程序的一部分。

二、源码解析

下面让我们分析一下的StopWatch的源码。

2.1 成员变量

/**
 * 秒表的标识符。
 * 当我们有多个秒表的输出并需要在日志或控制台输出中区分它们时，这很方便。
 */
private final String id;

/**
 * 任务列表
 */
@Nullable
private List<TaskInfo> taskList = new ArrayList<>(1);

/** 当前任务的开始时间。 */
private long startTimeNanos;

/** 当前任务的名称。 */
@Nullable
private String currentTaskName;

@Nullable
private TaskInfo lastTaskInfo;

/** 任务数量。 */
private int taskCount;

/** 总运行时间。 */
private long totalTimeNanos;

2.2 start()

start()方法的逻辑如下：

首先判断当前的计时任务是否停止（currentTaskName标志了计时器是否正在被某个任务占用，isRunning()方法也表明了这一点）：
- currentTaskName不为空，计时器正在被某个任务占用，抛出异常；
- currentTaskName为空，计时器重新计时；
设置当前任务名称currentTaskName。
设置任务开始时间startTimeNanos，使用System.nanoTime()来测量每个Task耗时。

/**
 * 启动一个未命名的任务。
 * 如果在不首先调用此方法的情况下调用stop()或计时方法，则结果是未定义的。
 */
public void start() throws IllegalStateException {
	start("");
}

/**
 * 启动一个命名任务。
 * 如果在不首先调用此方法的情况下调用stop()或计时方法，则结果是未定义的。
 */
public void start(String taskName) throws IllegalStateException {
	if (this.currentTaskName != null) {
		throw new IllegalStateException("Can't start StopWatch: it's already running");
	}
	this.currentTaskName = taskName;
	this.startTimeNanos = System.nanoTime(); // 将当前时间赋值给startTimeNanos，注意这里用的是纳秒级别
}

2.3 stop()

stop()方法的逻辑如下：

首先判断当前的计时任务是否停止（currentTaskName标志了计时器是否正在被某个任务占用，isRunning()方法也表明了这一点）：
- currentTaskName不为空，有进行中的测量的任务；
- currentTaskName为空，没有进行中的测量的任务，抛出异常；
计算lastTime：System.nanoTime() - this.startTimeNanos;
计算totalTimeNanos：this.totalTimeNanos += lastTime;
结束任务，构造任务测量结果，存放到任务列表中
- 构造TaskInfo对象
- 判断该对象是否拓展taskList集合中
  - 是，存放在taskList集合中
  - 否，跳过，放弃本次任务收集
- currentTaskName置为null

/**
 * 停止当前任务。
 * 如果在没有调用至少一对start() / stop()方法的情况下调用计时方法，则结果是未定义的。
 */
public void stop() throws IllegalStateException {
	if (this.currentTaskName == null) {
		throw new IllegalStateException("Can't stop StopWatch: it's not running");
	}
	long lastTime = System.nanoTime() - this.startTimeNanos; // 这里是计算耗时的逻辑
	this.totalTimeNanos += lastTime;
	this.lastTaskInfo = new TaskInfo(this.currentTaskName, lastTime);
	if (this.taskList != null) {
		this.taskList.add(this.lastTaskInfo);
	}
	++this.taskCount;
	this.currentTaskName = null;
}

四、完整源码

package org.springframework.util;

import java.text.NumberFormat;
import java.util.ArrayList;
import java.util.List;
import java.util.Locale;
import java.util.concurrent.TimeUnit;

import org.springframework.lang.Nullable;

/**
 * 简单的秒表，允许对多个任务进行计时，显示总运行时间和每个指定任务的运行时间。
 * 隐藏System.nanoTime()的使用，提高应用程序代码的可读性，减少计算错误的可能性。
 * 注意，这个对象不是被设计为线程安全的，也不使用同步。
 * 该类通常用于在概念验证工作和开发过程中验证性能，而不是作为生产应用程序的一部分。
 * 从Spring Framework 5.2开始，以纳秒为单位跟踪和报告运行时间。
 * 从6.1开始，字符串呈现的默认时间单位是秒，其小数点的精度为纳秒。
 * 具有特定时间单位的自定义渲染可以通过prettyPrint(TimeUnit)请求。
 */
public class StopWatch {

	/**
	 * 秒表的标识符。
	 * 当我们有多个秒表的输出并需要在日志或控制台输出中区分它们时，这很方便。
	 */
	private final String id;

	@Nullable
	private List<TaskInfo> taskList = new ArrayList<>(1);

	/** 当前任务的开始时间。 */
	private long startTimeNanos;

	/** 当前任务的名称。 */
	@Nullable
	private String currentTaskName;

	@Nullable
	private TaskInfo lastTaskInfo;

	private int taskCount;

	/** 总运行时间。 */
	private long totalTimeNanos;


	/**
	 * 构造一个新的秒表。
	 * 不启动任何任务。
	 */
	public StopWatch() {
		this("");
	}

	/**
	 * 用给定的id构造一个新的秒表。
	 * 当我们有多个秒表的输出并需要区分它们时，id很方便。
	 * 不启动任何任务。
	 */
	public StopWatch(String id) {
		this.id = id;
	}


	/**
	 * 获取在构造中指定的StopWatch的id。
	 */
	public String getId() {
		return this.id;
	}

	/**
	 * 配置秒表是否。
	 * TaskInfo数组是随着时间构建的。当使用秒表执行数百万个任务时，将此设置为false;否则，TaskInfo结构会占用过多的内存。
	 * 默认为true。
	 */
	public void setKeepTaskList(boolean keepTaskList) {
		this.taskList = (keepTaskList ? new ArrayList<>() : null);
	}


	/**
	 * 启动一个未命名的任务。
	 * 如果在不首先调用此方法的情况下调用stop()或计时方法，则结果是未定义的。
	 */
	public void start() throws IllegalStateException {
		start("");
	}

	/**
	 * 启动一个命名任务。
	 * 如果在不首先调用此方法的情况下调用stop()或计时方法，则结果是未定义的。
	 */
	public void start(String taskName) throws IllegalStateException {
		if (this.currentTaskName != null) {
			throw new IllegalStateException("Can't start StopWatch: it's already running");
		}
		this.currentTaskName = taskName;
		this.startTimeNanos = System.nanoTime();
	}

	/**
	 * 停止当前任务。
	 * 如果在没有调用至少一对start() / stop()方法的情况下调用计时方法，则结果是未定义的。
	 */
	public void stop() throws IllegalStateException {
		if (this.currentTaskName == null) {
			throw new IllegalStateException("Can't stop StopWatch: it's not running");
		}
		long lastTime = System.nanoTime() - this.startTimeNanos;
		this.totalTimeNanos += lastTime;
		this.lastTaskInfo = new TaskInfo(this.currentTaskName, lastTime);
		if (this.taskList != null) {
			this.taskList.add(this.lastTaskInfo);
		}
		++this.taskCount;
		this.currentTaskName = null;
	}

	/**
	 * 确定秒表当前是否正在运行。
	 */
	public boolean isRunning() {
		return (this.currentTaskName != null);
	}

	/**
	 * 获取当前运行任务的名称(如果有)。
	 */
	@Nullable
	public String currentTaskName() {
		return this.currentTaskName;
	}

	/**
	 * 把最后一个任务作为StopWatch.TaskInfo对象。
	 */
	public TaskInfo lastTaskInfo() throws IllegalStateException {
		Assert.state(this.lastTaskInfo != null, "No tasks run");
		return this.lastTaskInfo;
	}

	/**
	 * 把最后一个任务作为StopWatch.TaskInfo对象。
	 * 弃用从6.1开始，支持lastTaskInfo()
	 */
	@Deprecated(since = "6.1")
	public TaskInfo getLastTaskInfo() throws IllegalStateException {
		return lastTaskInfo();
	}

	/**
	 * 获取最后一个任务的名称。
	 * 弃用从6.1开始，支持lastTaskInfo()
	 * 可以查看StopWatch.TaskInfo.getTaskName()
	 */
	@Deprecated(since = "6.1")
	public String getLastTaskName() throws IllegalStateException {
		return lastTaskInfo().getTaskName();
	}

	/**
	 * 获取最后一个任务花费的时间(以纳秒为单位)。
	 * 弃用从6.1开始，支持lastTaskInfo()
	 * 可以查看StopWatch.TaskInfo.getTimeNanos()
	 */
	@Deprecated(since = "6.1")
	public long getLastTaskTimeNanos() throws IllegalStateException {
		return lastTaskInfo().getTimeNanos();
	}

	/**
	 * 获取最后一个任务所花费的时间(以毫秒为单位)。
	 * 弃用从6.1开始，支持lastTaskInfo()
	 * 可以查看StopWatch.TaskInfo.getTimeMillis()
	 */
	@Deprecated(since = "6.1")
	public long getLastTaskTimeMillis() throws IllegalStateException {
		return lastTaskInfo().getTimeMillis();
	}

	/**
	 * 获取已执行任务的数据数组。
	 * 可以查看setKeepTaskList
	 */
	public TaskInfo[] getTaskInfo() {
		if (this.taskList == null) {
			throw new UnsupportedOperationException("Task info is not being kept!");
		}
		return this.taskList.toArray(new TaskInfo[0]);
	}

	/**
	 * 获取计时的任务数。
	 */
	public int getTaskCount() {
		return this.taskCount;
	}

	/**
	 * 获取所有任务的总时间(以纳秒为单位)。
	 * 可以查看getTotalTime(TimeUnit)
	 */
	public long getTotalTimeNanos() {
		return this.totalTimeNanos;
	}

	/**
	 * 获取所有任务的总时间(以毫秒为单位)。
	 * 可以查看getTotalTime(TimeUnit)
	 */
	public long getTotalTimeMillis() {
		return TimeUnit.NANOSECONDS.toMillis(this.totalTimeNanos);
	}

	/**
	 * 以秒为单位获取所有任务的总时间。
	 * 可以查看getTotalTime(TimeUnit)
	 */
	public double getTotalTimeSeconds() {
		return getTotalTime(TimeUnit.SECONDS);
	}

	/**
	 * 以请求的时间单位获取所有任务的总时间(以纳秒为精度的小数点)。
	 */
	public double getTotalTime(TimeUnit timeUnit) {
		return (double) this.totalTimeNanos / TimeUnit.NANOSECONDS.convert(1, timeUnit);
	}


	/**
	 * 生成一个表，描述以秒为单位执行的所有任务(以纳秒为精度的小数点)。
	 * 对于自定义报告，调用getTaskInfo()并直接使用数据。
	 */
	public String prettyPrint() {
		return prettyPrint(TimeUnit.SECONDS);
	}

	/**
	 * 生成一个表，描述在请求的时间单位内执行的所有任务(以纳秒为精度的小数点)。
	 * 对于自定义报告，调用getTaskInfo()并直接使用数据。
	 */
	public String prettyPrint(TimeUnit timeUnit) {
		NumberFormat nf = NumberFormat.getNumberInstance(Locale.ENGLISH);
		nf.setMaximumFractionDigits(9);
		nf.setGroupingUsed(false);

		NumberFormat pf = NumberFormat.getPercentInstance(Locale.ENGLISH);
		pf.setMinimumIntegerDigits(2);
		pf.setGroupingUsed(false);

		StringBuilder sb = new StringBuilder(128);
		sb.append("StopWatch '").append(getId()).append("': ");
		String total = (timeUnit == TimeUnit.NANOSECONDS ?
				nf.format(getTotalTimeNanos()) : nf.format(getTotalTime(timeUnit)));
		sb.append(total).append(" ").append(timeUnit.name().toLowerCase(Locale.ENGLISH));
		int width = Math.max(sb.length(), 40);
		sb.append("\n");

		if (this.taskList != null) {
			String line = "-".repeat(width) + "\n";
			String unitName = timeUnit.name();
			unitName = unitName.charAt(0) + unitName.substring(1).toLowerCase(Locale.ENGLISH);
			unitName = String.format("%-12s", unitName);
			sb.append(line);
			sb.append(unitName).append("  %       Task name\n");
			sb.append(line);

			int digits = total.indexOf('.');
			if (digits < 0) {
				digits = total.length();
			}
			nf.setMinimumIntegerDigits(digits);
			nf.setMaximumFractionDigits(10 - digits);

			for (TaskInfo task : this.taskList) {
				sb.append(String.format("%-14s", (timeUnit == TimeUnit.NANOSECONDS ?
						nf.format(task.getTimeNanos()) : nf.format(task.getTime(timeUnit)))));
				sb.append(String.format("%-8s",
						pf.format(task.getTimeSeconds() / getTotalTimeSeconds())));
				sb.append(task.getTaskName()).append('\n');
			}
		}
		else {
			sb.append("No task info kept");
		}

		return sb.toString();
	}

	/**
	 * 获取以秒为单位的总运行时间的简短描述。
	 */
	public String shortSummary() {
		return "StopWatch '" + getId() + "': " + getTotalTimeSeconds() + " seconds";
	}

	/**
	 * 生成一个信息字符串，描述在几秒钟内执行的所有任务。
	 */
	@Override
	public String toString() {
		StringBuilder sb = new StringBuilder(shortSummary());
		if (this.taskList != null) {
			for (TaskInfo task : this.taskList) {
				sb.append("; [").append(task.getTaskName()).append("] took ").append(task.getTimeSeconds()).append(" seconds");
				long percent = Math.round(100.0 * task.getTimeSeconds() / getTotalTimeSeconds());
				sb.append(" = ").append(percent).append('%');
			}
		}
		else {
			sb.append("; no task info kept");
		}
		return sb.toString();
	}


	/**
	 * 嵌套类，用于保存在StopWatch中执行的一个任务的数据。
	 */
	public static final class TaskInfo {

		private final String taskName;

		private final long timeNanos;

		TaskInfo(String taskName, long timeNanos) {
			this.taskName = taskName;
			this.timeNanos = timeNanos;
		}

		/**
		 * 获取该任务的名称
		 */
		public String getTaskName() {
			return this.taskName;
		}

		/**
		 * 获取此任务花费的时间(以纳秒为单位)
		 */
		public long getTimeNanos() {
			return this.timeNanos;
		}

		/**
		 * 获取此任务花费的时间(以豪秒为单位)
		 */
		public long getTimeMillis() {
			return TimeUnit.NANOSECONDS.toMillis(this.timeNanos);
		}

		/**
		 * 获取此任务花费的时间(以秒为单位)
		 */
		public double getTimeSeconds() {
			return getTime(TimeUnit.SECONDS);
		}

		/**
		 * 以请求的时间单位获取此任务所花费的时间(以纳秒为精度的小数点)。
		 */
		public double getTime(TimeUnit timeUnit) {
			return (double) this.timeNanos / TimeUnit.NANOSECONDS.convert(1, timeUnit);
		}
	}

}