Measuring Java Code Execution Time with Spring's StopWatch

Introduction

Measuring code execution time is a vital step in trying to write efficient applications. Temporal awareness of your code on a machine that might be serving a great deal of users lets you plan further, accounting for the execution time.

In multi-threaded systems, it's also useful to measure the execution time of individual Threads or asynchronous tasks.

Since there's no built-in, convenient way to measure code execution in Java - for Spring-based solutions, we've been introduced to the StopWatch tool.

In this tutorial, we'll take a look at how to measure code execution time in Java with Spring's StopWatch.

Spring's StopWatch Class

The StopWatch is a utility class, residing in the util package. It has a very simple API and allows us to time named tasks, groups of tasks and the total running time of a program.

This class is normally used to check the performance of code during the development phase, rather than a part of production applications.

Note: It is worth noting that StopWatch is not thread-safe.

It tracks the time in nanoseconds, relying on System.nanoTime(), which is what people have been doing manually to time the execution of their code.

Measuring Code Execution Time with StopWatch

The StopWatch belongs to the core util package of Spring:

<dependency>
    <groupId>org.springframework</groupId>
    <artifactId>spring-core</artifactId>
</dependency>

Naturally, it's also present in the spring-boot-starter-web dependency:

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-web</artifactId>
</dependency>

The API of StopWatch boils down to creating an instance and calling start() and stop() - as if timing the code with an actual stopwatch. When starting the timing, you can also provide a String to be used as a name or annotation for the associated task. This helps differentiate them in the results.

A task is simply the period between a start() and stop() call. For each task, created when a StopWatch starts - its name and execution time are saved in a TaskInfo instance, and added to the task list.

Let's go ahead and create a task, with a name and measure a piece of code's execution time:

StopWatch timeMeasure = new StopWatch();

timeMeasure.start("Task 1");
Thread.sleep(1000);
timeMeasure.stop();

System.out.println("Last task time in Millis: " 
             + timeMeasure.getLastTaskMillis());

This results in:

Last task time in Millis: 1009

You can access the sum of all tasks through getTotalTimeSeconds(), getTotalTimeMillis() and getTotalTimeNanos().

You can also access the last task of the StopWatch through getLastTaskInfo(), which returns a TaskInfo instance. This instance contains information on the last task such as the name and how long it took in seconds, milliseconds and nanoseconds:

StopWatch stopWatch = new StopWatch();

stopWatch.start("Task 1");
Thread.sleep(1000);
stopWatch.stop();

System.out.println(stopWatch.getLastTaskInfo().getTaskName());

System.out.println(stopWatch.getLastTaskInfo().getTimeMillis());

This now results in:

Task 1
1008

When dealing with multiple tasks, a really handy method is the prettyPrint() method - which prints all of the records in a table-like fashion, with simple formatting:

// Naming this StopWatch instance
StopWatch stopWatch = new StopWatch("Measure Code Execution");
    
stopWatch.start("1. Task");
Thread.sleep(2000);
stopWatch.stop();
    
stopWatch.start("2. Task");
Thread.sleep(5000);
stopWatch.stop();
 
stopWatch.start("3. Task");
Thread.sleep(3000);
stopWatch.stop();
  
System.out.println(stopWatch.prettyPrint());

Output:

StopWatch 'Measure Code Execution': running time = 10012348500 ns
---------------------------------------------
ns         %     Task name
---------------------------------------------
2002729600  020%  1. Task
5006985700  050%  2. Task
3002633200  030%  3. Task

Note: If we're using StopWatch to measure the code execution time for a large number of intervals (on the order of hundreds of thousands or millions) - the TaskInfo list will consume a significant portion of your working memory. You can turn it off via:

stopWatch.setKeepTaskList(false);

Conclusion

In this tutorial, we took a look at the StopWatch utility class - Spring's answer to the inherent lack of time measurement tools in Java.