10

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.
Mark
  • 5,089
  • 2
  • 20
  • 31
  • 1
    You should use `System.nanoTime()` instead of `System.currentTimeMillis()` ([Link](https://stackoverflow.com/questions/1770010/how-do-i-measure-time-elapsed-in-java)). – Turamarth Oct 23 '18 at 10:28
  • Instead of rolling your own, why not use an existing micro-benchmark, for example like the one described [here](https://www.baeldung.com/java-microbenchmark-harness)? – Robby Cornelissen Oct 23 '18 at 10:29
  • 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. – Mark Oct 23 '18 at 10:35
  • 2
    @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. – Mark Oct 23 '18 at 10:57
  • OK, I reopened it. – Henry Oct 23 '18 at 11:00
  • 1
    In an application container, you could have a method [interceptor](https://www.tutorialspoint.com/ejb/ejb_interceptors.htm) annotation triggering the performance measure. – SME_Dev Oct 23 '18 at 11:05
  • This is a close duplicate to https://stackoverflow.com/questions/180158/how-do-i-time-a-methods-execution-in-java (Which is different to the micro benchmark question linked earlier) – Ryan Leach Oct 23 '18 at 11:23
  • 1
    @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. – Mark Oct 23 '18 at 11:26
  • 1
    For what it's worth, I didn't flag. a close-duplicate as opposed to duplicate. (maybe near-duplicate would have been better) – Ryan Leach Oct 23 '18 at 11:41

3 Answers3

3

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.

Joop Eggen
  • 107,315
  • 7
  • 83
  • 138
  • 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? – Mark Oct 23 '18 at 11:36
  • @Mark 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. – Joop Eggen Oct 23 '18 at 11:38
1

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).

Ryan Leach
  • 4,262
  • 5
  • 34
  • 71
  • 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? – Mark Oct 23 '18 at 11:13
  • 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. – Ryan Leach Oct 23 '18 at 11:16
1

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");
}
Lii
  • 11,553
  • 8
  • 64
  • 88