StopWatch – Let Spring calculate the interface time for you

Wechat search programmers take off can add my public number, to ensure that a dry goods update ~

(Reply keyword “information” can obtain the essence of younger brother for many years, understand all understand ~)

Are you still bothered by interface timing?

Are you still copying System.currentTimemillis () mindlessly?

Struggling to locate “slow code bottlenecks”?

I will introduce a artifact — StopWatch! Let Spring do the time counting for you!

The background,

I believe you must have encountered some of the problems I mentioned at the beginning. I also believe that you must have written the following repeated meaningless timing code. When a piece of code takes too long and calls too many interfaces, we have to do step-by-step statistics to see which interfaces are holding us back and identify interface performance bottlenecks. It is not surprising to have the following code. I often wonder if there is a tool to help us count the time and ratio of interfaces, and to help us analyze slow interfaces and slow calls. Until I met him — StopWatch!

    public static void func1(a) 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));

    }
Copy the code

Second, the first met

When I first met StopWatch, my colleague told me that there was something that could replace your end-start code. I hold a contemptuous attitude to look at his code, see StopWatch, chase into the source code roughly a look, this is not in the final analysis with the System. NanoTime to reduce it, with me what is the difference. Of course, if the story had ended there, there would have been no blog. There is only one reason why I decided to pursue it deeply. It belongs to Spring, and Spring uses it to do interface time statistics as shown in the figure below:

Because of my personal idolatry of Spring, I think everything he does is good! I decided to take a good look at this StopWatch, and as it turns out, it smells good!

Third, explore

3.1 the use of

The cognition of all things is from the beginning of use, so let’s see how it is used. The code at the beginning, when replaced with StopWatch, will look like this:

    public static void func2(a) 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());

    }
Copy the code

At first glance, it looks like there’s more code than there was before. But if you actually write it, it’s actually a lot easier to write than the first one. Just control the start and end of each piece of code, and don’t care which time minus which time. The results were even better:

As shown in the figure, StopWatch not only correctly records the execution time of the last task, but also gives an accurate task execution time (nanosecond level) and time ratio at the end. In fact, StopWatch can also record the process of the whole task, for example, which tasks have been completed and each time can be obtained through methods. Such as:

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("-- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --");
});
Copy the code

The result is as follows:

This link and information may not seem useful at the moment, as I will explain in a later extended section. Okay

3.2 the source code

It’s the old rule. Start small. Look at the usage, let’s look at the source code. Take a look at the attributes that make up 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. * Unique Id of this instance, used to distinguish between logs or console output. * /
	private final String id;

	/** * Whether to keep a taskList * Each time the timer is stopped, the current task is put into the list to record the task link and timing analysis */
	private boolean keepTaskList = true;

	/** ** list of tasks */
	private final List<TaskInfo> taskList = new LinkedList<>();

	/** Start time of the current task. */
	/** Start time of the current task. */
	private long startTimeNanos;

	/** Name of the current task. */
	/** Current task name. */
	@Nullable
	private String currentTaskName;

	@Nullable
	/** Last mission info. */
	private TaskInfo lastTaskInfo;

	/** Total number of tasks. */
	private int taskCount;

	/** Total running time. */
	/** Total task time. */
	private long totalTimeNanos;
Copy the code

StopWatch internally holds an internal class TaskInfo with two properties

	/**
	 * 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(a) { return this.taskName; }

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

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

		/**
		 * Get the time in seconds this task took.
		 * @see #getTimeMillis()
		 * @see #getTimeNanos()
		 */
		public double getTimeSeconds(a) { return nanosToSeconds(this.timeNanos); }}Copy the code

Here it is important to mention that some readers may see the source code with me posted here is not the same. This is due to the uniform use of milliseconds in StopWatch prior to Spring 5.2, known as TimeMillis. In Spring 5.2 and later, the switch to nanosecond is TimeNanos.

I’m sure you can pretty much guess what the implementation is, but it just maintains a linked list of tasks, and then it starts with a time, it ends with a time, and it subtracts when it takes. Here because of space reasons only put start and stop two methods of source. If you are interested in the rest of the way, please consult the source code (spring – the core module org. Springframework. Util. StopWatch class).

	/**
	 * 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;
		// Start with a start time
		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(a) throws IllegalStateException {
		if (this.currentTaskName == null) {
			throw new IllegalStateException("Can't stop StopWatch: it's not running");
		}
		// Calculate the duration at the end, in nanoseconds, from the current time minus the start time
		long lastTime = System.nanoTime() - this.startTimeNanos;
		// The total duration increases
		this.totalTimeNanos += lastTime;
		/ / record lastTaskInfo
		this.lastTaskInfo = new TaskInfo(this.currentTaskName, lastTime);
		// If a list of tasks is recorded, put the task in the list
		if (this.keepTaskList) {
			this.taskList.add(this.lastTaskInfo); } + +this.taskCount;
		this.currentTaskName = null;
	}
Copy the code

3.3 develop

Here I want to talk about the use of StopWatch, in fact, the above code is defined in this method, and then use in the same method is the most basic usage. Here are a few ideas. (Usage is not limited to this, you can open their own development ~)

1. At the Controller layer or Service layerStopWatchIn theThreadLocalIn the middle. The same is used throughout the Service invocation chainStopWatchObject records the time and path of method calls. Finally, the time ratio of the method is generated at the end to locate performance bottlenecks.
2. usingSpring-AOPMethods are used at the beginning and end of each methodStopWatchRecord the interface time.
3. Declare an annotation, usingSpring-AOPAnd annotated ways, custom analysis with annotated methods time-consuming.

In these cases, the task invocation link described in Section 3.1 becomes very important. This call link will be a very important means of locating time.

Four,

Everything has two sides. Finally, let’s look at the advantages and disadvantages

Advantages:

• This helps you collect time statistics. By specifying a task name and analyzing the time ratio, you can clearly locate the interface and invocation that consumes a lot of time.
• Record the entire task link for full-link analysis.
• You focus only on the start and end points of your code time, not on which time is required minus which time

Disadvantages:

• The sameStopWatchYou can start only one task and cannot collect statistics on the time consumed by the Include class. For example, if task A contains task B, only one task can be enabledStopWatchThe instance
• A task cannot be inserted, for example, task A, task B, and task A. The execution time of task B cannot be isolated.

---

The more you read, the more you find your ignorance. Keep Fighting!

Welcome friendly communication, do not spray ~

Hope can help~

My blog will be synchronized to OSCHINA community, this is my OSCHINA ID: OSC_13668000, invite you to join: www.oschina.net/sharing-pla…