Timing Code segments execution time inside a large method

Question

I would like to know how long it takes to run many code segments inside a large method.

I use System.nanoTime() to record the timestamp. Afterwards, I subtract two timestamps, such as nano2-nano1, to get the execution durations.

public static void largeMehod() {
    
    long nano1 = System.nanoTime();
    System.out.println("it takes a long time ~N sec");
    
    long nano2 = System.nanoTime();
    System.out.println("it takes a long time ~N sec");
    
    long nano3 = System.nanoTime();
    System.out.println("it takes a long time ~N sec");
    
    long nano4 = System.nanoTime();
    System.out.printf("put together, 1-2=%s 2-3=%s 3-4=%s%n", nano2 - nano1, nano3 - nano2, nano4 - nano3);
}

Problem here:

1. I have to manually write code to name those variables and format the strings, it is inefficient and likely to introduce bugs
2. I have to remove such inefficient codes before I submit it to production, which can also introduce bugs

what I tried

With guava stopwatch:

public static void largeMehod() {

    Stopwatch stopwatch = Stopwatch.createStarted();

    System.out.println("it takes a long time ~N sec");

    stopwatch.stop();
    Duration elapse12 = stopwatch.elapsed();
    
    stopwatch.reset();
    stopwatch.start();
    System.out.println("it takes a long time ~N sec");
    stopwatch.stop();
    Duration elapsed23 = stopwatch.elapsed();

    stopwatch.reset();
    stopwatch.start();
    System.out.println("it takes a long time ~N sec");
    stopwatch.stop();
    Duration elapsed34 = stopwatch.elapsed();

    System.out.printf("put together, 1-2=%s 2-3=%s 3-4=%s%n", elapse12, elapsed23, elapsed34);
}

It does help a little for naming variables, but it looks messier with .reset() and .stop() method calls.

Could you give me some advice? Any advice is appreciated.

Answer 1

You can chain methods together: stopwatch.reset().start(). Also, you don't need to stop before calling elapsed(). So you can shorten your code like this:

stopwatch.reset().start();
System.out.println("it takes a long time ~N sec");
Duration elapsed23 = stopwatch.elapsed();

You can even create a method that runs some code and times it:

public static Duration measureTime(Callable<Void> code) {
    Stopwatch stopwatch = Stopwatch.createStarted();
    code.call();
    return stopwatch.elapsed();
}

and use it like this:

Duration elapsed23 = measureTime(() -> {
    System.out.println("it takes a long time ~N sec");
});

However, if the measureTime method is the only place where you use Stopwatch then you don't need to load this class just for this usage. You can just use the standard System class:

public static Duration measureTime(Callable<Void> code) {
    long start = System.nanoTime();
    code.call();
    return Duration.ofNanos(System.nanoTime() - start);
}

If you are doing this all over in a large application, you should consider using Open Telemetry. This would be the "professional" way, but it is a very steep learning curve and it also requires a certain infrastructure to be in place at deployment, so it's something you should only do if you are already using software for viewing metrics.