1, The simplest timing

In our program, it is necessary to time an operation or method so that we can observe whether the operation or method meets our expectations. Therefore, when we first come into contact with Java, we can write code like the following to time:

public static void main(String[] args) {
    Long startTime = System.currentTimeMillis();

    doSomeThing();

    Long endTime = System.currentTimeMillis();
    Long elapsedTime = (endTime - startTime) / 1000;
    System.out.println("Total time:" + elapsedTime + "s");
}
// Used to simulate some operations
private static void doSomeThing()  {
    try {
        Thread.sleep(1000);
    } catch (InterruptedException e) {
        e.printStackTrace();
    }
}

In fact, there is no problem with this, and it can run well, but one thing is not very good. I pay too much attention to the output information. Let's understand a more elegant timing method;

2, StopWatch class

To use it, first you need to introduce the Spring core package into your Maven. Of course, Spring MVC and Spring Boot have automatically introduced the package:

<!-- spring Core package -->
<dependency>
    <groupId>org.springframework</groupId>
    <artifactId>spring-core</artifactId>
    <version>${spring.version}</version>
</dependency>

Now our timing posture may become as follows:

public static void main(String[] args) {
    StopWatch clock = new StopWatch();

    clock.start("Start task 1");
    doSomeThing();
    clock.stop();

    clock.start("Start task 2");
    doSomeThing();
    clock.stop();

    System.out.println(clock.prettyPrint());
}

// Used to simulate some operations
private static void doSomeThing() {
    try {
        Thread.sleep(1000);
    } catch (InterruptedException e) {
        e.printStackTrace();
    }
}

Finally, we use the prettyPrint() method class of StopWatch class to format our output. Run the program and you will find that your program outputs such things:

StopWatch '': running time (millis) = 2009
-----------------------------------------
ms     %     Task name
-----------------------------------------
01005  050%  Start task 1
01004  050%  Start task 2

Not only the total time, but also the occupation time and percentage of occupation time of each task, which may be more elegant than our own output;

How is the StopWatch class implemented?

When you poke the StopWatch source code, you will see familiar things in less than 200 lines of code:

    public void start(String taskName) throws IllegalStateException {
        if (this.currentTaskName != null) {
            throw new IllegalStateException("Can't start StopWatch: it's already running");
        } else {
            this.currentTaskName = taskName;
            this.startTimeMillis = System.currentTimeMillis();
        }
    }

    public void stop() throws IllegalStateException {
        if (this.currentTaskName == null) {
            throw new IllegalStateException("Can't stop StopWatch: it's not running");
        } else {
            long lastTime = System.currentTimeMillis() - this.startTimeMillis;
            this.totalTimeMillis += lastTime;
            this.lastTaskInfo = new StopWatch.TaskInfo(this.currentTaskName, lastTime);
            if (this.keepTaskList) {
                this.taskList.add(this.lastTaskInfo);
            }

            ++this.taskCount;
            this.currentTaskName = null;
        }
    }

You will find that this class implements a queue called taskList using LinkedList,

Then, the System.currentTimeMillis() method is also used to obtain the time at the beginning of each time,

In addition to calculating the time-consuming each time, a TaskInfo object describing the current task will be built and put into the taskList queue.

When the prettyPrint() method is executed, the tasks are taken out from the taskList queue in turn, and then some formatting operations are performed:

    public String shortSummary() {
        return "StopWatch '" + this.getId() + "': running time (millis) = " + this.getTotalTimeMillis();
    }

    public String prettyPrint() {
        StringBuilder sb = new StringBuilder(this.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);
            StopWatch.TaskInfo[] var4 = this.getTaskInfo();
            int var5 = var4.length;

            for(int var6 = 0; var6 < var5; ++var6) {
                StopWatch.TaskInfo task = var4[var6];
                sb.append(nf.format(task.getTimeMillis())).append("  ");
                sb.append(pf.format(task.getTimeSeconds() / this.getTotalTimeSeconds())).append("  ");
                sb.append(task.getTaskName()).append("\n");
            }
        }

        return sb.toString();
    }

reference resources: https://cloud.tencent.com/developer/article/1478313