What's a clean way to time code execution in Java?

Question

It can be handy to time code execution so you know how long things take. However, I find the common way this is done sloppy since it's supposed to have the same indentation, which makes it harder to read what's actually being timed.

long start = System.nanoTime();

// The code you want to time

long end = System.nanoTime();
System.out.printf("That took: %d ms.%n", TimeUnit.NANOSECONDS.toMillis(end - start));

An attempt

I came up with the following, it looks way better, there are a few advantages & disadvantages:

Advantages:

• It's clear what's being timed because of the indentation
• It will automatically print how long something took after code finishes

Disadvantages:

• This is not the way AutoClosable is supposed to be used (pretty sure)
• It creates a new instance of TimeCode which isn't good
• Variables declared within the try block are not accessible outside of it

It can be used like this:

 try (TimeCode t = new TimeCode()) {
     // The stuff you want to time
 }

The code which makes this possible is:

class TimeCode implements AutoCloseable {

    private long startTime;

    public TimeCode() {
        this.startTime = System.nanoTime();
    }

    @Override
    public void close() throws Exception {
        long endTime = System.nanoTime();
        System.out.printf("That took: %d ms%n",
                TimeUnit.NANOSECONDS.toMillis(endTime - this.startTime));
    }

}

The question

My question is:

• Is my method actually as bad as I think it is
• Is there a better way to time code execution in Java where you can clearly see what's being timed, or will I just have to settle for something like my first code block.

Astringent

You should use System.nanoTime() instead of System.currentTimeMillis() (Link). – Fauman

Instead of rolling your own, why not use an existing micro-benchmark, for example like the one described here? – Waxy

It's not so much about benchmarking and validating that it's fast, it's more about displaying how long something took if that makes sense. For example showing how long saving a file took. That's why I didn't bother with nanoTime() since it doesn't have to be that accurate perse. – Astringent

@Henry Hi Henry, I would argue that it's not a duplicate, considering it's not about micro benchmarking in the sense that I do not want to test how fast or slow code runs. But it's more about logging, to either files or console to indicate how fast something happened in production. – Astringent

In an application container, you could have a method interceptor annotation triggering the performance measure. – Sal

@RyanTheLeach Again I would argue it's not, that question is about how to time code, this one is about a cleaner, more readable way to time code, this question already indicates knowledge of how to time code. – Astringent

For what it's worth, I didn't flag. a close-duplicate as opposed to duplicate. (maybe near-duplicate would have been better) – Fourpence

Answer 1

You solution is just fine.

A less expressive way would be to wrap your code to be timed in a lambda.

public void timeCode(Runnable code) {
    ...
    try {
        code.run();
    } catch ...
    }
    ...
}

timeCode(() -> { ...code to time... });

You would probably like to catch the checked exceptions and pass them to some runtime exception or whatever.

Dall

I really like this solution, with your comment/edit you mean that you add something like throw new RuntimeException(e), with e being the exception that got caught, right? – Astringent

@Astringent yes, there are already similar exceptions used for streams, but I cannot remember which one. Rather than RuntimeException I would tend to IllegalStateException or such. – Dall

Answer 2

You method is great as-is. We use something similar professionally but written in C#.

One thing that I would potentially add, is proper logging support, so that you can toggle those performance numbers, or have them at a debug or info level.

Additional improvements that I would be considering, is creating some static application state, (abusing thread locals) so that you can nest these sections, and have summary breakdowns.

See https://github.com/aikar/minecraft-timings for a library that does this for minecraft modding (written in java).

Fourpence

Yes if I'm going this route those are things I will things like that, this was just a minimal example. So creating a new object instance is just something you make do with? – Astringent

Java's escape analysis is usually pretty good, and it would be rare that a single object being created for something that seems to take long enough to warrant being measured and output should be a performance consideration over the nicer syntax. That said, you could just have a start/stop pair of static methods to reduce the allocation, but that would be rather error prone. – Fourpence

Answer 3

I think the solution that is suggested in the question text is too indirect and non-idiomatic to be suitable for production code. (But it looks like a neat tool to get quick timings of stuff during development.)

Both the Guava project and the Apache Commons include stop-watch classes. If you use any of them the code will be easier to read and understand, and these classes have more built-in functionality too.

Even without using a try-with-resource statement the section that is being measured can be enclosed in a block to improve clarity:

// Do things that shouldn't be measured

{
    Stopwatch watch = Stopwatch.createStarted();

    // Do things that should be measured

    System.out.println("Duration: " + watch.elapsed(TimeUnit.SECONDS) + " s");
}

Fecund