StopWatch Execution Time Monitor provided by Apache and Spring

Posted by anto91 on Sun, 28 Jul 2019 19:04:58 +0200

Preface

In encoding, we often want to get the execution time of a piece of code (a method). This article will introduce two time monitors (stopwatches) to let you handle this problem gracefully and flexibly.

Java Origin

This is the easiest way to understand and, of course, the most common: to write by ourselves.
For example, if we want to count the execution time of a piece of code, we often write this:

    public static void main(String[] args) {
        long startTime = System.currentTimeMillis();   //Get Start Time

        //Function body code
        //...

        long endTime = System.currentTimeMillis(); //Get End Time
        System.out.println("Program run time: " + (endTime - startTime) + "ms");
    }

Most of the time we use ms to represent it, but this is not flexible.If we're going to show nanoseconds, seconds, or even minutes, we'll have to do it ourselves (convert millisecond values to ~)

Perhaps after JDK8, we'll be a little more flexible in doing this: we can do this:

    public static void main(String[] args) {
        Instant start = Instant.now();
        //doSomething();
        Instant end = Instant.now();

        Duration duration = Duration.between(start, end);
        System.out.println("millis = " + duration.toMillis());
    }

This one is more flexible than the one above.But there are still some drawbacks: the steps are slightly more complex, generally not elegant enough, and not so flexible.
This article then introduces a tool for this problem: StopWatch Execution Time Monitor.It provides us with a lot of convenience and elegance to count the execution time of our programs.

StopWatch relies on an additional Jar: commons-lang3 or spring-core, but since both Jars are required in Java development, the dependency on compatibility can be ignored

StopWatch has many open source frameworks that offer similar functionality, such as Apache's commons-lang3 and, of course, Spring Framework itself, which are described here ~

StopWatch for Commons-lang3

Apache provides this Task Execution Monitor with a rich, powerful (more powerful than Spring) capability and flexibility, such as the following classic utility cases:

    public static void main(String[] args) throws Exception {
        StopWatch watch = StopWatch.createStarted(); //start immediately after creation, commonly used
        //StopWatch watch = new StopWatch();
        //watch.start();

        Thread.sleep(1000);
        System.out.println("Statistics from start to run time:" + watch.getTime() + "ms"); //1000ms

        Thread.sleep(1000);
        watch.split();
        System.out.println("from start To this point:" + watch.getTime());
        System.out.println("Run time from start to first entry point:" + watch.getSplitTime()); //2245

        Thread.sleep(1000);
        watch.split();
        System.out.println("Run time from start to second entry point:" + watch.getSplitTime());

        watch.reset(); //start method must be used after reset
        watch.start();
        Thread.sleep(1000);
        System.out.println("The run time from restart to current is:" + watch.getTime()); //1000

        watch.suspend(); //suspend
        Thread.sleep(6000); //Analog pause for 6 seconds

        watch.resume(); //suspend above, to recalculate here, you need to restore
        System.out.println("The time to execute after recovery is:" + watch.getTime()); //1000 Note if this value is 1000 at this time

        watch.stop();
        System.out.println("Time Spent"" + watch.getTime() + "ms"); //1002ms
        System.out.println("Time Spent"" + watch.getTime(TimeUnit.SECONDS) + "s"); //1s can be converted directly to s

    }

Print results:

Statistics from start to run: 1007ms
 Time from start to this moment: 2008
 Run time from start to first entry point: 2008
 Run time from start to second entry point: 3009
 The run time from restart to current is: 1000
 The time to execute after recovery is: 1000
 Time Spent"1001ms
 Time Spent"1s

This is the basic way StopWatch is used, so you can see how powerful it is, and of course, how complex it is.

Interpretation of Core Principles

The principle is relatively simple, just look at the source code to see:

// @since 2.0
public class StopWatch {
    // The static method @since 3.5 appears a little later.
    public static StopWatch createStarted() {
        final StopWatch sw = new StopWatch();
        sw.start();
        return sw;
    }

    // These member variables are the core of implementation ~~~~~~~~~~
    private State runningState = State.UNSTARTED;
    private SplitState splitState = SplitState.UNSPLIT;
    private long startTime;
    // Think: Why do I have to record a Millis Time here with nonaTime???
    // Because nanoTime can only take differences (time consuming), the old API, getStartTime(), relies on MillsTime~~
    private long startTimeMillis;
    private long stopTime;
    
    // Visible: whether the start method can be called many times is related to the state
    public void start() {
        if (this.runningState == State.STOPPED) {
            throw new IllegalStateException("Stopwatch must be reset before being restarted. ");
        }
        if (this.runningState != State.UNSTARTED) {
            throw new IllegalStateException("Stopwatch already started. ");
        }
        this.startTime = System.nanoTime();
        this.startTimeMillis = System.currentTimeMillis();
        this.runningState = State.RUNNING;
    }

    // When stopping a table, the most important thing is to record the stopTime value ~~and then mark the status
    public void stop() {
        if (this.runningState != State.RUNNING && this.runningState != State.SUSPENDED) {
            throw new IllegalStateException("Stopwatch is not running. ");
        }
        if (this.runningState == State.RUNNING) {
            this.stopTime = System.nanoTime();
        }
        this.runningState = State.STOPPED;
    }

    // State becomes non-start state...
    public void reset() {
        this.runningState = State.UNSTARTED;
        this.splitState = SplitState.UNSPLIT;
    }

    // Pause: stopTime also gives a value
    public void suspend() {
        if (this.runningState != State.RUNNING) {
            throw new IllegalStateException("Stopwatch must be running to suspend. ");
        }
        this.stopTime = System.nanoTime();
        this.runningState = State.SUSPENDED;
    }

    // The two methods are to get the difference
    public long getTime() {
        return getNanoTime() / NANO_2_MILLIS;
    }
    // @since 3.5
    public long getTime(final TimeUnit timeUnit) {
        return timeUnit.convert(getNanoTime(), TimeUnit.NANOSECONDS);
    }

    // @since 2.4 Old API This is called Get Start Time (when started)
    public long getStartTime() {
        if (this.runningState == State.UNSTARTED) {
            throw new IllegalStateException("Stopwatch has not been started");
        }
        // System.nanoTime is for elapsed time
        return this.startTimeMillis;
    }
}

You can see that the principle is very simple, just packed with functions such as pause, reply, split, etc.

Use Details

==getTime What's the difference between getSplitTime and getSplitTime?==
To illustrate the problem, let's also look at getNanoTime() and getSplitNanoTime():

    public long getNanoTime() {
        if (this.runningState == State.STOPPED || this.runningState == State.SUSPENDED) {
            return this.stopTime - this.startTime;
        } else if (this.runningState == State.UNSTARTED) {
            return 0;
        } else if (this.runningState == State.RUNNING) {
            return System.nanoTime() - this.startTime;
        }
        throw new RuntimeException("Illegal running state has occurred.");
    }

     public long getSplitNanoTime() {
        if (this.splitState != SplitState.SPLIT) {
            throw new IllegalStateException("Stopwatch must be split to get the split time. ");
        }
        return this.stopTime - this.startTime;
    }

We found that:

getSplit... The Split method must be called before the related method can be called

The source code for the spilit() method is as follows:

    public void split() {
        if (this.runningState != State.RUNNING) {
            throw new IllegalStateException("Stopwatch is not running. ");
        }
        this.stopTime = System.nanoTime();
        this.splitState = SplitState.SPLIT;
    }

After calling the split method, the state of the watch changes to SPLIT.And, and, stopTime is set to the current time.So here our stopTime stops, and getSplitNanoTime() is called, returning the time difference between start and split.So with this method, you can insert stopTime() (a little bit of a queue-jumping push), and then output (queue-jumping first, and finally output)~

getTime() takes the current timestamp, minus startTime, and generally does not involve the value of stopTime, so splitTime is much more flexible to process, but getTime() is usually sufficient.

Spring's TopWatch

Spring provides this task monitor, which I still like to use, because one can help my colleagues monitor multiple tasks and is very easy to use.Let's start with a simple use case:

Note: It is very important that a monitor can record the execution time of multiple tasks.
For example, we can record the time consuming of multiple pieces of code and print them at once~

    public static void main(String[] args) throws Exception {
        // Intensely give an id to each stopwatch so that you can view the log more accurately
        // As for Id, I think it is possible to give UUID~
        StopWatch sw = new StopWatch(UUID.randomUUID().toString());

        sw.start("Get up");
        Thread.sleep(1000);
        System.out.println("Current Task Name:" + sw.currentTaskName());
        sw.stop();

        sw.start("Washing");
        Thread.sleep(2000);
        System.out.println("Current Task Name:" + sw.currentTaskName());
        sw.stop();

        sw.start("Lock the door");
        Thread.sleep(500);
        System.out.println("Current Task Name:" + sw.currentTaskName());
        sw.stop();

        System.out.println(sw.prettyPrint()); // This method of printing is very friendly and percentage analysis when we log
        System.out.println(sw.shortSummary());
        System.out.println(sw.currentTaskName()); // stop followed by null


        // Information about the last task
        System.out.println(sw.getLastTaskName());
        System.out.println(sw.getLastTaskInfo());

        // Total task time if you want to get details of each task (including its task name, time consuming, etc.)
        System.out.println("Total time spent on all tasks:" + sw.getTotalTimeMillis());
        System.out.println("Total number of tasks:" + sw.getTaskCount());
        System.out.println("All task details:" + sw.getTaskInfo()); // Get all the jobs
    }

Print:

Current Task Name: Get up
 Current Task Name: Washing
 Current Task Name: Lock Door
StopWatch 'd6ba9412-d551-4ba7-8b0e-1b7ccb42855d': running time (millis) = 3504
-----------------------------------------
ms     %     Task name
-----------------------------------------
01001 029% get up
 02000 057% rinse
 00503 014% Lock

StopWatch 'd6ba9412-d551-4ba7-8b0e-1b7ccb42855d': running time (millis) = 3504
null
 Lock the door
org.springframework.util.StopWatch$TaskInfo@2d554825
 Total time spent on all tasks: 3504
 Total number of tasks: 3
 All task details: [Lorg.springframework.util.StopWatch$TaskInfo;@68837a77

I personally prefer to use this monitor provided by Spring because it provides prettyPrint() printing for analysis in the log is very intuitive, and I think the multitask support provided is more practical, of course, just personal preference~

Last

Many times, writing code is also an art, and with this utility I feel more artistic.Hopefully we can have the heart to pursue something better, which is especially important for accepting new knowledge.This monitor is recommended here as a replacement for previous ones to allow your little buddies more flexibility in analyzing your code~

Knowledge Exchange

If the format of the article is confusing, click: Text Link-Text Link-Text Link-Text Link-Text Link-Text Link

==The last: If you find this article helpful, you might as well give a compliment.Of course, share it with your circle of friends so that more friends can see it is also authorized by the author himself ~==

** If you are interested in technical content, you can join the wx group: Java Engineering, Architect 3.
If the group QR code fails, add a wx number: fsx641385712 (or scan the wx QR code below).And note: the word "java joins the group" will be manually invited to join the group**

Topics: Java Spring Apache encoding

Programmer Think