StopWatch —— 让 Spring 来帮你计算接口时

微信搜索程序员的起飞之路可以加我公众号，保证一有干货就更新~

(回复关键字“资料”可以获取小弟多年精华，懂的都懂~)

是否还为接口计时而烦恼？

是否还在无脑的复制 System.currentTimeMillis() ？

是否还在为定位“慢代码瓶颈”而苦苦思索？

我为大家来介绍一个神器 —— StopWatch！让 Spring 来帮你统计时间吧！

一、背景

相信大家肯定遇到过我开头提到过的几种问题吧。也相信各位一定写过如下重复无意义的计时代码吧。当一段代码耗时极长，并且调用接口众多时，我们就不得不去分步统计看到底是哪个接口拖后腿，并以此定位接口性能瓶颈在哪里。那有如下代码就不奇怪了，我常常在想，是否有一套工具来帮我们统计接口耗时、占比，帮我们分析慢接口、慢调用呢？直到我遇到了他——StopWatch！

java复制代码    public static void func1() throws InterruptedException {
        long start = System.currentTimeMillis();
        System.out.println("phase1 do something....");
        Thread.sleep(1000);
        long phase1 = System.currentTimeMillis();
        System.out.printf("phase1 cost time %d ms\n", (phase1 - start));

        System.out.println("phase2 do something....");
        Thread.sleep(2000);
        long phase2 = System.currentTimeMillis();
        System.out.printf("phase2 cost time %d ms\n", (phase2 - phase1));

        System.out.println("phase3 do something....");
        Thread.sleep(3000);
        long phase3 = System.currentTimeMillis();
        System.out.printf("phase3 cost time %d ms\n", (phase3 - phase2));

        System.out.println("phase4 do something....");
        Thread.sleep(4000);
        long phase4 = System.currentTimeMillis();
        System.out.printf("phase4 cost time %d ms\n", (phase4 - phase3));

        long end = System.currentTimeMillis();
        System.out.printf("func1 cost %d ms\n", (end - start));

    }

二、初遇

初遇 StopWatch 是同事跟我讲，说有个东西可以替代你这里的 end - start 代码。我抱着不屑一顾的态度去看了一眼他的代码，看到了 StopWatch ，追进源码大致一看，这归根结底不还是用了 System.nanoTime 去减了一下，跟我的有什么区别呀。当然，如果故事终结于此，也就不会有这篇博客了。让我决定深追下去的只有一个原因，这个东西是 Spring 家的，而且 Spring 用了他去做接口时间的统计如图所示：

application

由于我个人对 Spring 的盲目崇拜，觉得他用啥都是好的！我决定好好研究一下这个 StopWatch，事实证明，真香！

三、深究

3.1 使用

对一切事物的认知，都是从使用开始，那就先来看看它的用法。开头一段的代码，在替换成 StopWatch 后，会如下所示：

java复制代码    public static void func2() throws InterruptedException {
        StopWatch stopWatch = new StopWatch("func2");

        stopWatch.start("phase1");
        System.out.println("phase1 do something....");
        Thread.sleep(1000);
        stopWatch.stop();
        System.out.printf("phase1 cost time %d ms\n", stopWatch.getLastTaskTimeMillis());

        stopWatch.start("phase2");
        System.out.println("phase2 do something....");
        Thread.sleep(2000);
        stopWatch.stop();
        System.out.printf("phase2 cost time %d ms\n", stopWatch.getLastTaskTimeMillis());

        stopWatch.start("phase3");
        System.out.println("phase3 do something....");
        Thread.sleep(3000);
        stopWatch.stop();
        System.out.printf("phase3 cost time %d ms\n", stopWatch.getLastTaskTimeMillis());

        stopWatch.start("phase4");
        System.out.println("phase4 do something....");
        Thread.sleep(4000);
        stopWatch.stop();
        System.out.printf("phase4 cost time %d ms\n", stopWatch.getLastTaskTimeMillis());

        System.out.printf("func1 cost %d ms\n", stopWatch.getTotalTimeMillis());
        System.out.println("stopWatch.prettyPrint() = " + stopWatch.prettyPrint());

    }

乍一眼看上去，是不是觉得这代码反而比之前的还要多了。但是如果实际写起来，实际上是要比第一种好写许多的。只管控制每段代码统计的开始和结束即可，不用关心是哪个时间减哪个时间。执行结果更为喜人：

执行结果

如图所示，StopWatch 不仅正确记录了上个任务的执行时间，并且在最后还可以给出精确的任务执行时间（纳秒级别）和耗时占比。其实并不止于此，StopWatch 还可以记录整个任务的走向流程，例如走过了哪几个任务，各个耗时都是可以通过方法拿到的。例如：

java复制代码System.out.println("stopWatch.getLastTaskName() = " + stopWatch.getLastTaskName());
System.out.println("stopWatch.getLastTaskInfo().getTimeMillis() = " + stopWatch.getLastTaskInfo().getTimeMillis());

Arrays.stream(stopWatch.getTaskInfo()).forEach(e->{
    System.out.println("e.getTaskName() = " + e.getTaskName());
    System.out.println("e.getTimeMillis() = " + e.getTimeMillis());
    System.out.println("---------------------------");
});

执行结果如下：

执行结果1

这个链路和信息目前看上去可能没什么用，在后面的扩展章节我会说明

3.2 源码

老规矩，由浅入深。看完用法，我们来看看源码。先看下组成 StopWatch 的属性

java复制代码	/**
	 * 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.
	 * 本实例的唯一 Id，用于在日志或控制台输出时区分的。
	 */
	private final String id;

	/**
	 * 是否保持一个 taskList 链表
	 * 每次停止计时时，会将当前任务放入这个链表，用以记录任务链路和计时分析
	 */
	private boolean keepTaskList = true;

	/**
	 * 任务链表
	 */
	private final List<TaskInfo> taskList = new LinkedList<>();

	/** Start time of the current task. */
	/** 当前任务的开始时间. */
	private long startTimeNanos;

	/** Name of the current task. */
	/** 当前任务名称. */
	@Nullable
	private String currentTaskName;

	@Nullable
	/** 最后一个任务的信息. */
	private TaskInfo lastTaskInfo;

	/** 任务总数. */
	private int taskCount;

	/** Total running time. */
	/** 总任务时间. */
	private long totalTimeNanos;

StopWatch 内部持有一个内部类 TaskInfo，内有两个属性

java复制代码	/**
	 * 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 timeNanos;

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

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

		/**
		 * Get the time in nanoseconds this task took.
		 * @since 5.2
		 * @see #getTimeMillis()
		 * @see #getTimeSeconds()
		 */
		public long getTimeNanos() { return this.timeNanos; }

		/**
		 * 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 nanosToSeconds(this.timeNanos); }

	}

这里要重点提一下，可能有的读者朋友看到的源码跟我这里贴出来的不一样。这是因为在 Spring 5.2 之前的 StopWatch 中统一使用的毫秒，即 TimeMillis 。而到 Spring 5.2 及其以后的版本，都统一改为纳秒即 TimeNanos 。

看完属性相信大家也差不多猜出来具体的实现了，不过就是维护了一个任务链表，然后开始的时候记一个时间，结束的时候记一个时间，最后取的时候减一下。此处由于篇幅原因就仅放 start 和 stop 两个方法的源码。大家如果对其余的方法感兴趣，请自行查阅源码（spring-core 模块 org.springframework.util.StopWatch 类）。

java复制代码	/**
	 * Start a named task.
	 * <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 {
		if (this.currentTaskName != null) {
			throw new IllegalStateException("Can't start StopWatch: it's already running");
		}
		this.currentTaskName = taskName;
		// 开始的时候记一个开始时间
		this.startTimeNanos = System.nanoTime();
	}

	/**
	 * Stop the current task.
	 * <p>The results are undefined if timing methods are called without invoking
	 * 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.nanoTime() - this.startTimeNanos;
		// 总时长增加
		this.totalTimeNanos += lastTime;
		// 记录 lastTaskInfo 
		this.lastTaskInfo = new TaskInfo(this.currentTaskName, lastTime);
		// 如果记录任务链表，则将此任务放进链表中
		if (this.keepTaskList) {
			this.taskList.add(this.lastTaskInfo);
		}
		++this.taskCount;
		this.currentTaskName = null;
	}

3.3 拓展

这里想聊一下 StopWatch 的用法，其实上述代码这种方法内定义一个，然后在同一个方法中使用是最基础的用法。下面给大家提供几个思路。（用法不仅限于此，大家可开动脑筋自行开发~）

在 Controller 层或 Service 层将 StopWatch 放入 ThreadLocal 当中。在整条 Service 调用链中，使用同一个 StopWatch 对象记录方法调用的耗时和路线。最后在结束时生成方法的耗时占比，以定位性能瓶颈。
利用 Spring-AOP 方式，在每个方法的开始和结束使用 StopWatch 记录接口耗时时间。
声明一个注解，利用 Spring-AOP 和注解的方式，自定义分析带注解的方法耗时。

在这几种情况下，3.1 章节中所说的任务调用链路就非常重要了。这个调用链路将是定位耗时的非常重要的手段。

四、总结

任何东西都有利害两面，最后我们来看下优点和缺点

优点：

方便统计耗时，通过指定任务名称和耗时占比分析，可以清晰明确的定位到耗时慢的接口和调用。
记录整条任务链路，方便全链路分析。
仅需要关注代码耗时的起始点和终点，无需关注到底需要哪个时间减哪个时间

缺点：

同一个 StopWatch 只能开启一个任务，无法统计 “包含” 类的耗时。例如 A 任务中包含 B 任务这种，只能再开启一个 StopWatch 实例
无法中间插入一个任务，例如先执行 A 任务，再执行 B 任务，再执行 A 任务。无法将 B 任务的执行时间单独隔离开。

读书越多越发现自己的无知，Keep Fighting！

欢迎友善交流，不喜勿喷~

Hope can help~

我的博客即将同步至 OSCHINA 社区，这是我的 OSCHINA ID：osc_13668000，邀请大家一同入驻：www.oschina.net/sharing-pla…

本文转载自: 掘金

开发者博客 – 和开发相关的这里全都有