Why is a particular Guava Stopwatch.elapsed() call much later than others? (output in post)

Question

I am working on a small game project and want to track time in order to process physics. After scrolling through different approaches, at first I had decided to use Java's Instant and Duration classes and now switched over to Guava's Stopwatch implementation, however, in my snippet, both of those approaches have a big gap at the second call of runtime.elapsed(). That doesn't seem like a big problem in the long run, but why does that happen?

I have tried running the code below as both in focus and as a Thread, in Windows and in Linux (Ubuntu 18.04) and the result stays the same - the exact values differ, but the gap occurs. I am using the IntelliJ IDEA environment with JDK 11.

Snippet from Main:

public static void main(String[] args) {

    MassObject[] planets = {
        new Spaceship(10, 0, 6378000)
    };

    planets[0].run();

}

This is part of my class MassObject extends Thread:

public void run() {
    // I am using StringBuilder to eliminate flushing delays.
    StringBuilder output = new StringBuilder();
    Stopwatch runtime = Stopwatch.createStarted();

    // massObjectList = static List<MassObject>;
    for (MassObject b : massObjectList) {
        if(b!=this) calculateGravity(this, b);
    }
    for (int i = 0; i < 10; i++) {
        output.append(runtime.elapsed().getNano()).append("\n");
    }
    System.out.println(output);
}

Stdout:

Thanks for your help.

If you call any method on `output` *before* the loop, does the elapsed time for the first iteration change? I suspect what you're measuring is class-loading or memory-allocation overhead related to the first time you're calling `append()` on a `StringBuilder` instance. — Daniel Pryden, May 01 '19 at 21:13
Not using my dupehammer powers because I'm not 100% sure it's the right answer, but if not a duplicate, this question is at very least closely related: [How do I write a correct micro-benchmark in Java?](https://stackoverflow.com/questions/504103/how-do-i-write-a-correct-micro-benchmark-in-java) — Daniel Pryden, May 01 '19 at 21:15
Hey Daniel, I have added an `append()` call before the loop and it changed nothing. Also, my question is more for the unexpected deviation - I believe `Stopwatch` is good enough to track elapsed time for my scale. — Emilis Kiškis, May 01 '19 at 21:23
It's not a question of tracking elapsed time, though. The question is *what is happening* during that time. You can't guarantee that lines of code are executed in the order you wrote them. Also, the first time is going to be the slowest time, and you may not hit full speed until you've looped thousands of times. Without more diagnostic information, it's impossible to tell you what is happening here. — Daniel Pryden, May 01 '19 at 23:02
Try calling `runtime.elapsed()` before the loop once. Probably `calculateGravity()` too. I'm pretty sure that the gap would go. It is most likely there due to class loading/initializing. — yegodm, May 02 '19 at 18:34
@yegodm I will experiment some more to get the initial delay gone. I just thought I am doing something wrong and the computer is acting up. — Emilis Kiškis, May 02 '19 at 18:45

ColinD · Accepted Answer · 2019-05-02T16:24:04.080

You're calling Duration.getNano() on the Duration returned by elapsed(), which isn't what you want.

The internal representation of a Duration is a number of seconds plus a nano offset for whatever additional fraction of a whole second there is in the duration. Duration.getNano() returns that nano offset, and should almost never be called unless you're also calling Duration.getSeconds().

The method you probably want to be calling is toNanos(), which converts the whole duration to a number of nanoseconds.

Edit: In this case that doesn't explain what you're seeing because it does appear that the nano offsets being printed are probably all within the same second, but it's still the case that you shouldn't be using getNano().

The actual issue is probably some combination of classloading or extra work that has to happen during the first call, and/or JIT improving performance of future calls (though I don't think looping 10 times is necessarily enough that you'd see much of any change from JIT).

I like that you not only provided a pretty good guess of an answer, but also pointed out the incorrect usage of `getNano()`. Thank you! — Emilis Kiškis, May 02 '19 at 18:44
On the other hand... check out this pastebin: https://pastebin.com/JcARm43w I just don't understand what's going on - only the SECOND line of durations is way longer, despite me adding extra calls before and such. This is a mystery. — Emilis Kiškis, May 02 '19 at 18:55

Why is a particular Guava Stopwatch.elapsed() call much later than others? (output in post)

1 Answers1