StopWatch的源码介绍和使用，优雅记录任务耗时

• StopWatch 是Spring框架提供的一个任务执行计时工具，位于org.springframework.util包下面。
• StopWatch 就是为了提高代码的可读性，减少可能出现的计算错误而设计的。
• 同样，我们平时的开发中，也经常会要用到记录某个任务执行时间的操作，往往需要在任务的开始之前记录startTime和任务结束后计算最终的耗时time-consuming。
• StopWatch 可以更加优雅的帮助我们实现多个串行任务的时间统计，并计算出每个任务的时间占比。

一、源码注释

package org.springframework.util;

import java.text.NumberFormat;
import java.util.LinkedList;
import java.util.List;

import org.springframework.lang.Nullable;

/**
 * Simple stop watch, allowing for timing of a number of tasks,
 * exposing total running time and running time for each named task.
 *
 * <p>Conceals use of {@code System.currentTimeMillis()}, improving the
 * readability of application code and reducing the likelihood of calculation errors.
 *
 * <p>Note that this object is not designed to be thread-safe and does not
 * use synchronization.
 *
 * <p>This class is normally used to verify performance during proof-of-concepts
 * and in development, rather than as part of production applications.
 *
 * @author Rod Johnson
 * @author Juergen Hoeller
 * @author Sam Brannen
 * @since May 2, 2001
 */
 /**
  * 翻译：
  * 一个简单的停止观察器，支持多个任务执行，并对外暴露每个任务的运行时间和总运行时间 。
  * 对外隐藏System.currentTimeMillis()的使用，提高代码的可读性，并减少可能存在的计算错误。
  * 非线程安全且不需要使用同步机制的、用于性能验证但不作为生产程序的一部分。 
  * 设置为线程不安全的，是因为此工具一般运行于某个对象实例的一个方法栈中，不存在线程安全问题
  */
public class StopWatch {

	/**StopWatch的id,别于识别多个StopWatch的日志输出
	 * Identifier of this stop watch.
	 * Handy when we have output from multiple stop watches
	 * and need to distinguish between them in log or console output.
	 */
	private final String id;
	// 默认保存任务列表信息
	private boolean keepTaskList = true;
	// 当前StopWatch所执行的任务列表
	private final List<TaskInfo> taskList = new LinkedList<>();
	
	/** Start time of the current task */
	private long startTimeMillis;
	// 任务的名称，也用于判断当前任务的运行状态
	/** Name of the current task */
	@Nullable
	private String currentTaskName;
	// 总是执行StopWatch中执行stop的任务
	@Nullable
	private TaskInfo lastTaskInfo;
	// 当前StopWatch的任务数量
	private int taskCount;
	// 当前StopWatch执行所有任务之后的总耗时
	/** Total running time */
	private long totalTimeMillis;


	/**
	 * Construct a new stop watch. Does not start any task.
	 */
	public StopWatch() {
		// 默认id为空串
		this("");
	}

	/**
	 * Construct a new stop watch with the given id.
	 * Does not start any task.
	 * @param id identifier for this stop watch.
	 * Handy when we have output from multiple stop watches
	 * and need to distinguish between them.
	 */
	public StopWatch(String id) {
		this.id = id;
	}


	/**
	 * Return the id of this stop watch, as specified on construction.
	 * @return the id (empty String by default)
	 * @since 4.2.2
	 * @see #StopWatch(String)
	 */
	public String getId() {
		return this.id;
	}

	/**是否开启任务列表统计，当不需要知道各个任务执行占比和各个任务的执行时间时可以关闭，只记录总耗时和总任务数和最后一个任务的执行信息
	 * Determine whether the TaskInfo array is built over time. Set this to
	 * "false" when using a StopWatch for millions of intervals, or the task
	 * info structure will consume excessive memory. Default is "true".
	 */
	public void setKeepTaskList(boolean keepTaskList) {
		this.keepTaskList = keepTaskList;
	}


	/**
	 * Start an unnamed task. The results are undefined if {@link #stop()}
	 * or timing methods are called without invoking this method.
	 * @see #stop()
	 */
	public void start() throws IllegalStateException {
		// 默认任务名称为空串
		start("");
	}

	/**
	 * Start a named task. The results are undefined if {@link #stop()}
	 * or timing methods are called without invoking this method.
	 * @param taskName the name of the task to start
	 * @see #stop()
	 */
	public void start(String taskName) throws IllegalStateException {
		// 当前StopWatch如果已经有正在执行的任务，不能继续执行，需要等待上一个任务完成
		if (this.currentTaskName != null) {
			throw new IllegalStateException("Can't start StopWatch: it's already running");
		}
		// 记录当前任务名称，同时也会阻止
		this.currentTaskName = taskName;
		// 
		this.startTimeMillis = System.currentTimeMillis();
	}

	/**
	 * Stop the current task. The results are undefined if timing
	 * methods are called without invoking at least one pair
	 * {@code start()} / {@code stop()} methods.
	 * @see #start()
	 */
	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;
		this.totalTimeMillis += lastTime;
		// 设置最后一个任务信息
		this.lastTaskInfo = new TaskInfo(this.currentTaskName, lastTime);
		// 关闭keepTaskList之后则不会有所有任务的占比计算
		if (this.keepTaskList) {
			this.taskList.add(this.lastTaskInfo);
		}
		// 累计任务数
		++this.taskCount;
		// 设置当前任务名为空，让后面的任务可以开始执行
		this.currentTaskName = null;
	}

	/**
	 * Return whether the stop watch is currently running.
	 * @see #currentTaskName()
	 */
	public boolean isRunning() {
		// 根据任务名称是否为空判断当前是否有任务在执行
		return (this.currentTaskName != null);
	}

	/** 当任务stop之后返回null
	 * Return the name of the currently running task, if any.
	 * @since 4.2.2
	 * @see #isRunning()
	 */
	@Nullable
	public String currentTaskName() {
		return this.currentTaskName;
	}


	/**至少有一个任务执行完成之后才有值
	 * Return the time taken by the last task.
	 */
	public long getLastTaskTimeMillis() throws IllegalStateException {
		if (this.lastTaskInfo == null) {
			throw new IllegalStateException("No tasks run: can't get last task interval");
		}
		return this.lastTaskInfo.getTimeMillis();
	}

	/**至少有一个任务执行完成之后才有值
	 * Return the name of the last task.
	 */
	public String getLastTaskName() throws IllegalStateException {
		if (this.lastTaskInfo == null) {
			throw new IllegalStateException("No tasks run: can't get last task name");
		}
		return this.lastTaskInfo.getTaskName();
	}

	/**至少有一个任务执行完成之后才有值
	 * Return the last task as a TaskInfo object.
	 */
	public TaskInfo getLastTaskInfo() throws IllegalStateException {
		if (this.lastTaskInfo == null) {
			throw new IllegalStateException("No tasks run: can't get last task info");
		}
		return this.lastTaskInfo;
	}


	/**
	 * Return the total time in milliseconds for all tasks.
	 */
	public long getTotalTimeMillis() {
		return this.totalTimeMillis;
	}

	/**
	 * Return the total time in seconds for all tasks.
	 */
	public double getTotalTimeSeconds() {
		return this.totalTimeMillis / 1000.0;
	}

	/**
	 * Return the number of tasks timed.
	 */
	public int getTaskCount() {
		return this.taskCount;
	}

	/**
	 * Return an array of the data for tasks performed.
	 */
	public TaskInfo[] getTaskInfo() {
		if (!this.keepTaskList) {
			throw new UnsupportedOperationException("Task info is not being kept!");
		}
		return this.taskList.toArray(new TaskInfo[0]);
	}


	/**简短的输出StopWatch的总耗时
	 * Return a short description of the total running time.
	 */
	public String shortSummary() {
		return "StopWatch '" + getId() + "': running time (millis) = " + getTotalTimeMillis();
	}

	/**以列表的形式输出所有任务的执行情况
	 * Return a string with a table describing all tasks performed.
	 * For custom reporting, call getTaskInfo() and use the task info directly.
	 */
	public String prettyPrint() {
		StringBuilder sb = new StringBuilder(shortSummary());
		sb.append('\n');
		if (!this.keepTaskList) {
			sb.append("No task info kept");
		}
		else {
			sb.append("-----------------------------------------\n");
			sb.append("ms     %     Task name\n");
			sb.append("-----------------------------------------\n");
			NumberFormat nf = NumberFormat.getNumberInstance();
			nf.setMinimumIntegerDigits(5);
			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(pf.format(task.getTimeSeconds() / getTotalTimeSeconds())).append("  ");
				sb.append(task.getTaskName()).append("\n");
			}
		}
		return sb.toString();
	}

	/**输出所有任务的执行耗时和占比
	 * Return an informative string describing all tasks performed
	 * For custom reporting, call {@code 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());
				long percent = Math.round((100.0 * task.getTimeSeconds()) / getTotalTimeSeconds());
				sb.append(" = ").append(percent).append("%");
			}
		}
		else {
			sb.append("; no task info kept");
		}
		return sb.toString();
	}


	/**TaskInfo 内部类，记录任务名称和执行时间
	 * Inner class to hold data about one task executed within the stop watch.
	 */
	public static final class TaskInfo {

		private final String taskName;

		private final long timeMillis;

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

		/**
		 * Return the name of this task.
		 */
		public String getTaskName() {
			return this.taskName;
		}

		/**
		 * Return the time in milliseconds this task took.
		 */
		public long getTimeMillis() {
			return this.timeMillis;
		}

		/**
		 * Return the time in seconds this task took.
		 */
		public double getTimeSeconds() {
			return (this.timeMillis / 1000.0);
		}
	}

}

二、测试

package com.qy.toolkit.test;

import org.springframework.util.StopWatch;

import java.util.Random;

/**
 * @author qi.yu319
 */
public class TestStopWatch {
    /**
     * 随机器
     */
    private static final Random RD = new Random();

    public static void main(String[] args) {
        StopWatch stopWatch = new StopWatch("测试StopWatch工具ID-" + getRangeOfZeroToThousandNumber());
        // 关闭ktl，则记录总任务数
        // stopWatch.setKeepTaskList(false);
        // 第一个任务
        stopWatch.start("taskOneName");
        theadSleepRandomMs();
        stopWatch.stop();
        // 第二个任务
        stopWatch.start("taskTwoName");
        theadSleepRandomMs();
        stopWatch.stop();
        // 第三个任务
        stopWatch.start("taskThreeName");
        theadSleepRandomMs();
        stopWatch.stop();

        System.out.printf("当前任务总数[stopWatch.getTaskCount() ==>] %d 个%n", stopWatch.getTaskCount());
        System.out.printf("当前任务总耗时[stopWatch.getTotalTimeMillis() ==>] %d ms%n", stopWatch.getTotalTimeMillis());
        System.out.printf("当前任务总耗时[stopWatch.getTotalTimeNanos() ==>] %d ns%n", stopWatch.getTotalTimeNanos());
        System.out.printf("打印执行结果[stopWatch.toString() ==>] %s%n", stopWatch.toString());
        System.out.printf("格式化输出结果[stopWatch.prettyPrint() ==>] %s%n", stopWatch.prettyPrint());
    }

    /**
     * 当前线程随机睡眠0-1000ms
     */
    public static void theadSleepRandomMs() {
        try {
            Thread.sleep(getRangeOfZeroToThousandNumber());
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }

    /**
     * 获取0-1000随机数
     */
    public static int getRangeOfZeroToThousandNumber() {
        return RD.nextInt(1001);
    }
}

测试结果：

当前任务总数[stopWatch.getTaskCount() ==>] 3 个
当前任务总耗时[stopWatch.getTotalTimeMillis() ==>] 1575 ms
当前任务总耗时[stopWatch.getTotalTimeNanos() ==>] 1575668300 ns
打印执行结果[stopWatch.toString() ==>] StopWatch '测试StopWatch工具ID-937': running time = 1575668300 ns; [taskOneName] took 419070300 ns = 27%; [taskTwoName] took 529838400 ns = 34%; [taskThreeName] took 626759600 ns = 40%
格式化输出结果[stopWatch.prettyPrint() ==>] StopWatch '测试StopWatch工具ID-937': running time = 1575668300 ns
---------------------------------------------
ns         %     Task name
---------------------------------------------
419070300  027%  taskOneName
529838400  034%  taskTwoName
626759600  040%  taskThreeName

关闭stopWatch.setKeepTaskList(false)的执行结果：

当前任务总数[stopWatch.getTaskCount() ==>] 3 个
当前任务总耗时[stopWatch.getTotalTimeMillis() ==>] 1845 ms
当前任务总耗时[stopWatch.getTotalTimeNanos() ==>] 1845702600 ns
打印执行结果[stopWatch.toString() ==>] StopWatch '测试StopWatch工具ID-715': running time = 1845702600 ns; no task info kept
格式化输出结果[stopWatch.prettyPrint() ==>] StopWatch '测试StopWatch工具ID-715': running time = 1845702600 ns
No task info kept
最后一个任务名称[stopWatch.getLastTaskName() ==>] taskThreeName
最后一个任务耗时[stopWatch.getLastTaskTimeMillis() ==>] 589 ms