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:

30700
1807000
1808900
1811600
1812400
1813300
1830200
1833200
1834500
1835500

Thanks for your help.

Answer 1

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