Why I get a negative elapsed time using System.nanoTime()?

Question

I'm trying to use following code with System.nanoTime() to measure the elapsed time of code.

public static void main(String[] args) throws Exception {
    while (true) {
        long start = System.nanoTime();
        for (int i = 0; i < 10000; i++)
            ;
        long end = System.nanoTime();
        long cost = end - start;
        if (cost < 0) {
            System.out.println("start: " + start + ", end: " + end + ", cost: " + cost);
        }
    }
}

And I get such result:

start: 34571588742886, end: 34571585695366, cost: -3047520
start: 34571590239323, end: 34571586847711, cost: -3391612
start: 34571651240343, end: 34571648928369, cost: -2311974
start: 34571684937094, end: 34571681543134, cost: -3393960
start: 34571791867954, end: 34571788878081, cost: -2989873
start: 34571838733068, end: 34571835464021, cost: -3269047
start: 34571869993665, end: 34571866950949, cost: -3042716
start: 34571963747021, end: 34571960656216, cost: -3090805
start: 34571965020545, end: 34571961637608, cost: -3382937
start: 34572010616580, end: 34572007613257, cost: -3003323

Why I get negative values?

(OS: windows xp sp3, java: jdk1.6u27)

Mendacity

can't reproduce on Linux with Java(TM) SE Runtime Environment (build 1.6.0_26-b03). Anyway, why do you complain? When Java was slow in the nineties people complained, now it's too fast, and people still complain :-) – Composition

Complain? I just can't find a correct way to measure code execution time. Nothing to do with fast or slow. – Mendacity

related: stackoverflow.com/questions/3274892/… – Composition

Can't reproduce on Mac with 1.6.0_26-b03 either. – Ironmaster

@Freewind, sorry I couldn't resist to joke a little – Composition

Can't reproduce as well on Mac OS X. Java version: "1.6.0_27" Java(TM) SE Runtime Environment (build 1.6.0_27-b07-386-11M3504) Java HotSpot(TM) 64-Bit Server VM (build 20.2-b06-386, mixed mode) – Teletypesetter

maybe it is a Neutrino machine. – Miculek

@Marek The javadocs say that a long can hold 292 years' worth of nanoseconds, so that's unlikely. – Jehovist

Can't reproduce on Vista 64bit with java.runtime.version=1.6.0_07-b06 – Succinct

It seems is a Windows XP thing. Time to upgrade maybe? – Composition

@Freewind: you are printing only the negative-cost-values. Do you only get negative values or are there just a few? – Adipose

@thomas, just a few. Most are positive. – Mendacity

Also related with high votes: stackoverflow.com/questions/510462/… – Fe

If somebody comes across this question in 2019 or later: this must not be an issue on any OS since OpenJDK 8u192 or in any versions released later up until February 2019, modulo unknown bugs that might still hide somewhere. See bugs.openjdk.java.net/browse/JDK-8184271 – Wharve

Answer 1

The nanoTime can be taken of the CPU clock cycle counter. As different CPUs can be started at slightly different times, the clock counter can be different on different CPUs. Linux corrects for this, but older versions of Windows do not. (I assume you have two CPUs which were started 3 ms apart)

You should also see positive jumps of over 2.5 ms occasionally.

Try

if (cost < 0 || cost > 2000000) {

And you should see some jump forward and some jump backward as the process is switched between CPUs.

Thekla

You are quite right. New results: -3494855, 4185715, -3562463, 3620073, 4175502, 3977789, -3500977, 4125248 – Mendacity

I would expect it to be almost alternating. Where there is an extra large positive result the process could be stopped and started again on the same CPU. – Thekla