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)

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 :-) — stivlo, Oct 23 '11 at 12:48
Complain? I just can't find a correct way to measure code execution time. Nothing to do with fast or slow. — Freewind, Oct 23 '11 at 12:53
related: http://stackoverflow.com/questions/3274892/why-is-my-system-nanotime-broken — stivlo, Oct 23 '11 at 12:53
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) — Martijn Courteaux, Oct 23 '11 at 12:55
@Marek The javadocs say that a `long` can hold 292 years' worth of nanoseconds, so that's unlikely. — millimoose, Oct 23 '11 at 12:59
Can't reproduce on Vista 64bit with java.runtime.version=1.6.0_07-b06 — Marcus, Oct 23 '11 at 12:59
@Freewind: you are printing only the negative-cost-values. Do you only get negative values or are there just a few? — thomas, Oct 23 '11 at 13:05
Also related with _high votes_: http://stackoverflow.com/questions/510462/is-system-nanotime-completely-useless — A.H., Oct 23 '11 at 13:31
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 https://bugs.openjdk.java.net/browse/JDK-8184271 — leventov, Feb 04 '19 at 03:23

score 16 · Accepted Answer · answered Oct 23 '11 at 13:11

16

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.

answered Oct 23 '11 at 13:11

Peter Lawrey

525,659
79
751
1,130

You are quite right. New results: -3494855, 4185715, -3562463, 3620073, 4175502, 3977789, -3500977, 4125248 – Freewind Oct 23 '11 at 13:24
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. – Peter Lawrey Oct 23 '11 at 13:25

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

1 Answers1

Linked