Weird processing time in repeated function calls, what could explain this?

Question

Given the code below and it's output, what could explain "1:" taking 80 times longer? If run in debug mode, the difference is reduced to 40x longer. Still a significant difference.

My first guess was JIT or other compiler optimizations. But that could be ruled out by adding multiple "timeNow()" and "println" calls (uncomment the commented section). Also, I've added following flags in an attempt to turn them off:

-Djava.compiler=NONE
-XX:-TieredCompilation

Any explanation or guesses would be appreciated.

public class Test {
    private static long lastTimestamp = -1;

    /**
     * Returns the elapsed time in microseconds since the last call to this method.
     * 
     * @return Elapsed time in microseconds if this is not the first call, otherwise
     *         returns -1 to indicate the first call.
     */
    public static long timeNow() {
        long currentTime = System.nanoTime();
        if (lastTimestamp == -1) {
            // This is the first call
            lastTimestamp = currentTime;
            return -1; // Indicate that this is the first call
        } else {
            long elapsedTime = currentTime - lastTimestamp;
            lastTimestamp = currentTime;
            return elapsedTime / 1000; // Return elapsed time in microseconds
        }
    }

    public static void main(String[] args) {
        timeNow();


//      timeNow();
//      timeNow();
//      timeNow();
//      
//      System.out.println("print");
//      System.out.println("print");
//      System.out.println("print");

        System.out.println("0: " + timeNow());
        System.out.println("1: " + timeNow());
        System.out.println("2: " + timeNow());
        System.out.println("3: " + timeNow());

    }
}

Output: (repeated multiple time with similar results)

0: 2
1: 17897
2: 334
3: 217

Answer 1

That the "1:" result takes longer might surprise you but is due to the differences in how we humans read the code in contrast to how the JVM executes the code. We tend to read the code from left to right, i.e. "call timeNow();, then execute System.out.println() with the result of "0: "+timeNow()", but the execution is more akin to

1. call timeNow() for the first time (first line in your main method)
2. push "0: " onto the operand stack
3. call timeNow() a second time and push its result onto the operand stack
4. concatenate "0: " and the result of converting the timeNow() result into a string (and this seems to involve some heavy class loading and code execution on the first call)
5. call System.out.println() with the result of the string concatenation
6. push "1: " onto the operand stack
7. call timeNow() a third time and push its result onto the operand stack
8. concatenate "1: " and the result of timeNow()

From your result it is especially the step 4 above (converting the result of timeNow() into a string and append it onto "0: ") that takes a long time.

You can verify this by changing your main method:

public static void main(String[] args) {
    timeNow();

    long i = 5;
    System.out.println("print " + i);

    System.out.println("0: " + timeNow());
    System.out.println("1: " + timeNow());
    System.out.println("2: " + timeNow());
    System.out.println("3: " + timeNow());
}

Executing this results in

print 5
0: 9001
1: 118
2: 81
3: 78

versus (removing that System.out.println("print " + i);)

 0: 2
 1: 9088
 2: 129
 3: 82

Note that it is important that the type of i is the same as the result type of timeNow() to activate the same code paths.