StopWatch：被忽视的任务执行时间监视器_综合

背景引入

学习源码的过程中，在springboot启动类的run方法里，看到这样一个对象，遂对其学习了一番。
在这里插入图片描述

简介

StopWatch是位于org.springframework.util包下的一个工具类，通过它可方便的对程序部分代码进行计时(ms级别)，适用于同步单线程代码块。用于代码性能监控，不用于实际业务。

允许多个任务的计时，暴露每个命名任务的总运行时间和运行时间。隐藏使用System.currentTimeMillis（），提高应用程序代码的可读性并减少计算错误的可能性。

源码学习

附上中文注释的源码

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;/*** 简单的秒表，允许对多个任务进行计时，公开总运行时间和每个命名任务的运行时间。* 隐藏 System.nanoTime()的使用，提高了应用程序代码的可读性，并减少了计算错误的可能性。* 请注意，此对象并非设计为线程安全的，并且不使用同步。* 此类通常用于在概念验证工作和开发过程中验证性能，而不是作为生产应用程序的一部分。* 从Spring Framework 5.2开始，以纳秒为单位跟踪和报告运行时间。*/
public class StopWatch {
    /*** 此秒表的标识符。* 当我们有多个秒表的输出并且需要在日志或控制台输出中进行区分时，此功能非常方便。*/private final String id;private boolean keepTaskList = true;private final List<TaskInfo> taskList = new LinkedList<>();/** 当前任务的开始时间。 */private long startTimeNanos;/** 当前任务的名称。 */@Nullableprivate String currentTaskName;@Nullableprivate TaskInfo lastTaskInfo;private int taskCount;/** 总运行时间。 */private long totalTimeNanos;/*** 构造一个新的秒表。* 不启动任何任务*/public StopWatch() {
    this("");}/*** 使用给定的ID构造一个新的StopWatch。* 当我们从多个秒表中输出并且需要区分它们时，该ID十分方便。* 不启动任何任务。*/public StopWatch(String id) {
    this.id = id;}/***获取此秒表的ID，该ID在构造时已指定。* 返回值：ID（默认为空字符串）*/public String getId() {
    return this.id;}/*** 配置StopWatch.TaskInfo数组是否随着时间的推移而构建。* 使用秒表进行数百万个间隔时，将其设置为false；否则，TaskInfo结构将消耗过多的内存。* 默认为true。*/public void setKeepTaskList(boolean keepTaskList) {
    this.keepTaskList = keepTaskList;}/*** 启动一个未命名的任务。* 如果在没有先调用该方法的情况下调用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.keepTaskList) {
    this.taskList.add(this.lastTaskInfo);}++this.taskCount;this.currentTaskName = null;}/*** 确定此秒表当前是否正在运行。*/public boolean isRunning() {
    return (this.currentTaskName != null);}/*** 获取当前正在运行的任务的名称（如果有）。*/@Nullablepublic String currentTaskName() {
    return this.currentTaskName;}/*** 获取上一个任务花费的时间（以纳秒为单位）。*/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();}/*** 获取上一个任务花费的时间（以毫秒为单位）。*/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();}/*** 获取上一个任务的名称。*/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();}/*** 获取最后一个任务作为StopWatch.TaskInfo对象。*/public TaskInfo getLastTaskInfo() throws IllegalStateException {
    if (this.lastTaskInfo == null) {
    throw new IllegalStateException("No tasks run: can't get last task info");}return this.lastTaskInfo;}/*** 获取所有任务的总时间（以纳秒为单位）。*/public long getTotalTimeNanos() {
    return this.totalTimeNanos;}/*** 获取所有任务的总时间（以毫秒为单位）。*/public long getTotalTimeMillis() {
    return nanosToMillis(this.totalTimeNanos);}/*** 获取所有任务的总时间（以秒为单位）。*/public double getTotalTimeSeconds() {
    return nanosToSeconds(this.totalTimeNanos);}/*** 获取计时的任务数。*/public int getTaskCount() {
    return this.taskCount;}/*** 获取执行的任务的数据数组。*/public TaskInfo[] getTaskInfo() {
    if (!this.keepTaskList) {
    throw new UnsupportedOperationException("Task info is not being kept!");}return this.taskList.toArray(new TaskInfo[0]);}/*** 获得总运行时间的简短描述。*/public String shortSummary() {
    return "StopWatch '" + getId() + "': running time = " + getTotalTimeNanos() + " ns";}/*** 生成带有描述所有已执行任务的表的字符串。* 对于自定义报告，请调用getTaskInfo()并直接使用任务信息。*/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("ns % Task name\n");sb.append("---------------------------------------------\n");NumberFormat nf = NumberFormat.getNumberInstance();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.getTimeNanos())).append(" ");sb.append(pf.format((double) task.getTimeNanos() / getTotalTimeNanos())).append(" ");sb.append(task.getTaskName()).append("\n");}}return sb.toString();}/*** 生成描述所有已执行任务的信息字符串* 对于自定义报告，请调用getTaskInfo（）并直接使用任务信息。*/@Overridepublic String toString() {
    StringBuilder sb = new StringBuilder(shortSummary());if (this.keepTaskList) {
    for (TaskInfo task : getTaskInfo()) {
    sb.append("; [").append(task.getTaskName()).append("] took ").append(task.getTimeNanos()).append(" ns");long percent = Math.round(100.0 * task.getTimeNanos() / getTotalTimeNanos());sb.append(" = ").append(percent).append("%");}}else {
    sb.append("; no task info kept");}return sb.toString();}private static long nanosToMillis(long duration) {
    return TimeUnit.NANOSECONDS.toMillis(duration);}private static double nanosToSeconds(long duration) {
    return duration / 1_000_000_000.0;}/*** 嵌套类，用于保存有关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 nanosToMillis(this.timeNanos);}/*** 获取此任务花费的时间（以秒为单位）。*/public double getTimeSeconds() {
    return nanosToSeconds(this.timeNanos);}}}

通过对该工具类源码的学习，我们可以通过调用该StopWatch的start()和stop()方法来分别记录被执行任务的开始时间和结束时间，在记录结束的时候，会维护一个链表类型的taskList属性，从而使该类能够记录多个任务，调用prettyPrint()方法可使最后的输出也可以对之前的记录的信息整理后统一输出，使多任务的计时结果更加直观。此外调用shortSummary()和getTotalTimeMillis()，可以查看程序执行时间。

代码演练

 /**不指定任务名*/
private static void test1() throws InterruptedException {
    StopWatch sw = new StopWatch();sw.start();//执行任务 do somethingThread.sleep(1000);sw.stop();System.out.println(sw.prettyPrint());
}输出：
StopWatch '': running time = 999802159 ns
---------------------------------------------
ns         %     Task name
---------------------------------------------
999802159  100%

/**指定任务名*/
private static void test2() throws InterruptedException {
    StopWatch sw = new StopWatch("测试任务");sw.start("任务-01");//执行任务 do somethingThread.sleep(1000);sw.stop();System.out.println(sw.prettyPrint());
}输出：
StopWatch '测试任务': running time = 1000332330 ns
---------------------------------------------
ns         %     Task name
---------------------------------------------
1000332330  100%  任务-01

/**多任务执行计时*/
private static void test3() throws InterruptedException {
    StopWatch sw = new StopWatch("测试任务");sw.start("任务-01");//执行任务01-do somethingThread.sleep(1000);sw.stop();sw.start("任务-02");//执行任务02-do somethingThread.sleep(500);sw.stop();System.out.println(sw.prettyPrint());
}输出：
StopWatch '测试任务': running time = 1500807290 ns
---------------------------------------------
ns         %     Task name
---------------------------------------------
1000139444  067%  任务-01
500667846  033%  任务-02

/** 工具类方法演示 */
private static void test4() throws InterruptedException {
    StopWatch sw = new StopWatch("测试任务");sw.start("任务-01");//执行任务01-do somethingThread.sleep(1000);sw.stop();sw.start("任务-02");//执行任务02-do something//获取当前任务名System.out.println("**************** currentTaskName() ****************");System.out.println(sw.currentTaskName());Thread.sleep(500);sw.stop();//获取简单说明的任务总时间System.out.println("**************** shortSummary() ****************");System.out.println(sw.shortSummary());//获取任务总时间System.out.println("**************** getTotalTimeMillis() ****************");System.out.println(sw.getTotalTimeMillis());//获取美化任务时间明细System.out.println("**************** prettyPrint() ****************");System.out.println(sw.prettyPrint());//获取任务信息System.out.println("**************** getTaskInfo() ****************");StopWatch.TaskInfo[] taskInfo = sw.getTaskInfo();Arrays.stream(taskInfo).forEach(task -> System.out.println("TaskName: "+task.getTaskName() +", TimeSeconds: " + task.getTimeSeconds() +", TimeMillis: " + task.getTimeMillis() +", TimeNanos: " + task.getTimeNanos()));
}输出：
**************** currentTaskName() ****************
任务-02
**************** shortSummary() ****************
StopWatch '测试任务': running time = 1500632807 ns
**************** getTotalTimeMillis() ****************
1500
**************** prettyPrint() ****************
StopWatch '测试任务': running time = 1500632807 ns
---------------------------------------------
ns         %     Task name
---------------------------------------------
999926384  067%  任务-01
500706423  033%  任务-02**************** getTaskInfo() ****************
TaskName: 任务-01, TimeSeconds: 0.999926384, TimeMillis: 999, TimeNanos: 999926384
TaskName: 任务-02, TimeSeconds: 0.500706423, TimeMillis: 500, TimeNanos: 500706423

归纳总结

StopWatch优缺点：

优点：

spring自带工具类，可直接使用
代码实现简单，使用更简单
统一归纳，展示每项任务耗时与占用总时间的百分比，展示结果直观
性能消耗相对较小，并且最大程度的保证了start与stop之间的时间记录的准确性
可在start时直接指定任务名字，从而更加直观的显示记录结果

缺点：

一个StopWatch实例一次只能开启一个task，不能同时start多个task，并且在该task未stop之前不能start一个新的task，必须在该task stop之后才能开启新的task，若要一次开启多个，需要new不同的StopWatch实例
代码侵入式使用，需要改动多处代码

实战应用

使用StopWatch记录请求摘要日志信息

@Slf4j
public class PerformanceInteceptor implements HandlerInterceptor {
    private ThreadLocal<StopWatch> stopWatchThreadLocal = new ThreadLocal<>();@Overridepublic boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
    StopWatch sw = new StopWatch();stopWatchThreadLocal.set(sw);sw.start();return true;}@Overridepublic void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
    stopWatchThreadLocal.get().stop();stopWatchThreadLocal.get().start();}@Overridepublic void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
    StopWatch sw = stopWatchThreadLocal.get();sw.stop();String method = handler.getClass().getSimpleName();if (handler instanceof HandlerMethod) {
    String beanType = ((HandlerMethod) handler).getBeanType().getName();String methodName = ((HandlerMethod) handler).getMethod().getName();method = beanType + "." + methodName;}// sw.getTotalTimeMillis(), 总执行时间//sw.getTotalTimeMillis() - sw.getLastTaskTimeMillis(), 执行方法体所需要的时间log.info("{};{};{};{};{}ms;{}ms;{}ms", request.getRequestURI(), method,response.getStatus(), ex == null ? "-" : ex.getClass().getSimpleName(),sw.getTotalTimeMillis(), sw.getTotalTimeMillis() - sw.getLastTaskTimeMillis(),sw.getLastTaskTimeMillis());stopWatchThreadLocal.remove();}
}