How Spring Boot source code implements StopWatch to elegantly count time consumption

Introduction

Yesterday, a golfer asked me if I could explain to him what the @SpringBootApplication annotation means and how Spring Boot operates, so I took him to pick up this annotation. The source code, as well as the source code of the run() method of the SpringApplication class, he understood it at once.

Don’t tell me, the process of looking at the source code is really interesting. No, I discovered an interesting point.

public ConfigurableApplicationContext run(String... args) {
	StopWatch stopWatch = new StopWatch();
	stopWatch.start();
	......
	stopWatch.stop();
}

Spring Boot uses StopWatch to count time consumption, and usually, we use System.currentTimeMillis() to count time consumption, right? Programming Meow???? There is such a piece of code in the open source project, when dealing with unified log processing aspects.

@Around("webLog()")
public Object doAround(ProceedingJoinPoint joinPoint) throws Throwable {
    long startTime = System.currentTimeMillis();
    long endTime = System.currentTimeMillis();
    webLog.setSpendTime((int) (endTime - startTime));
}

In comparison, we can find that System.currentTimeMillis() provided by JDK is not as concise and clear as StopWatch provided by Spring.

StopWatch usage

Especially when multi-tasking, StopWatch is so easy to use????!

// 创建一个 StopWatch 实例
StopWatch sw = new StopWatch("沉默王二是傻 X");
// 开始计时
sw.start("任务1");
Thread.sleep(1000);
// 停止计时
sw.stop();
System.out.printf("任务1耗时：%d%s.\n", sw.getLastTaskTimeMillis(), "ms");
sw.start("任务2");
Thread.sleep(1100);
sw.stop();
System.out.printf("任务2耗时：%d%s.\n", sw.getLastTaskTimeMillis(), "ms");
System.out.printf("任务数量：%s，总耗时：%ss.\n", sw.getTaskCount(), sw.getTotalTimeSeconds());

See, is it very simple?

• First create a new StopWatch object

• Then start to start timing

• Then stop to stop timing

• Finally get the time difference through sw.getLastTaskTimeMillis()

If you change it to System.currentTimeMillis(), you will die. You must declare it first There are several long-type local variables, and then the second one is subtracted from the first one, and the third one is subtracted from the second one. If you are a little careless (especially the CV method), it is easy to make mistakes.

In addition to the local time, you can also get the total time through sw.getTotalTimeSeconds().

Task 1 takes 1002ms.
Task 2 takes 1105ms.
Number of tasks: 2, total time: 2.107820109s.

In addition, StopWatch also provides a sw.prettyPrint() method to print out beautifully formatted results:

StopWatch 'Silent Wang Er is stupid': running time = 2108529351 ns
- --------------------------------------------------
ns       %   Task name
------------------------------------------------
1004338467 048% Task 1
1104190884 052% Task 2

has the time taken, the occupied percentage, and the task name, which is very clear.

In addition to Spring, the hutool tool library and the Apache common tool package provide their own StopWatch.

Looking at the StopWatch source code in the hutool tool library, we can see that this class actually comes from Spring's StopWatch.java, and its usage is exactly the same.

This shows that the author of hutool also thinks that Spring’s StopWatch is well written, hahaha????.

Use Beyond compare to compare

Using Beyond compare to compare, we can also find that except for one Chinese comment and one English comment, the codes are almost the same. The setKeepTaskList method is quite different.

That is to say, if you do not use Spring Family Bucket in your project and only use the hutool tool package, you can use hutool's StopWatch instead of System.currentTimeMillis ().

By analyzing the stop method source code of StopWatch:

public void stop() throws IllegalStateException {
	if (null == this.currentTaskName) {
		throw new IllegalStateException("Can't stop StopWatch: it's not running");
	}
	final long lastTime = System.nanoTime() - this.startTimeNanos;
	this.totalTimeNanos += lastTime;
	this.lastTaskInfo = new TaskInfo(this.currentTaskName, lastTime);
	if (null != this.taskList) {
		this.taskList.add(this.lastTaskInfo);
	}
	++this.taskCount;
	this.currentTaskName = null;
}

In fact, we can find that StopWatch is timed internally through System.nanoTime(), which is essentially the same as System.currentTimeMillis(). big.

nanoTime is more granular than currentTimeMillis. The former is in nanoseconds and the latter is in milliseconds.

#Note that both are native methods, that is to say, the granularity of the value actually depends on the underlying operating system.

After seeing this, everyone may suddenly realize that StopWatch is just System.currentTimeMillis() in a coat?

But the wonderful thing is that this coat is beautiful enough and elegant enough. StopWatch can record the name of each subtask and print the results in a format, which is more friendly especially for multi-task statistics.

Of course, in addition to choosing StopWatch of Spring and hutool, StopWatch of Apache commons-lang3 is also a good option, which is more flexible and changeable.

StopWatch sw = StopWatch.createStarted();
Thread.sleep(1000);
System.out.printf("耗时：%dms.\n", sw.getTime());

The other two create StopWatch objects through new, and commons-lang3 can also be completed through createStarted (create and start immediately) and create (create).

You can also call the suspend method to pause the timing, the resume method to resume the timing, and the reset method to restart the timing.

// 暂停计时
sw.suspend();
System.out.printf("暂停耗时：%dms.\n", sw.getTime());
// 恢复计时
sw.resume();
System.out.printf("恢复耗时：%dms.\n", sw.getTime());
// 停止计时
sw.stop();
System.out.printf("总耗时：%dms.\n", sw.getTime());
// 重置计时
sw.reset();
// 开始计时
sw.start();
System.out.printf("重置耗时：%dms.\n", sw.getTime());

The above is the detailed content of How Spring Boot source code implements StopWatch to elegantly count time consumption. For more information, please follow other related articles on the PHP Chinese website!