System.nanotime running slow?

Question

One of my friends showed me something he had done, and I was at a serious loss to explain how this could have happened: he was using a System.nanotime to time something, and it gave the user an update every second to tell how much time had elapsed (it Thread.sleep(1000) for that part), and it took seemingly forever (something that was waiting for 10 seconds took roughly 3 minutes to finish). We tried using millitime in order to see how much time had elapsed: it printed how much nanotime had elapsed every second, and we saw that for every second, the nanotime was moving by roughly 40-50 milliseconds every second.

I checked for bugs relating to System.nanotime and Java, but it seemed the only things I could find involved the nanotime suddenly greatly increasing and then stopping. I also browsed this blog entry based on something I read in a different question, but that didn't have anything that may cause it.

Obviously this could be worked around for this situation by just using the millitime instead; there are lots of workarounds to this, but what I'm curious about is if there's anything other than a hardware issue with the system clock or at least whatever the most accurate clock the CPU has (since that's what System.nanotime seems to use) that could cause it to run consistently slow like this?

long initialNano = System.nanoTime();
long initialMili = System.currentTimeMillis();
//Obviously the code isn't actually doing a while(true), 
//but it illustrates the point
while(true) {
    Thread.sleep(1000);
    long currentNano = System.nanoTime();
    long currentMili = System.currentTimeMillis();
    double secondsNano = ((double) (currentNano - initialNano))/1000000000D;
    double secondsMili = ((double) (currentMili - initialMili))/1000D;
    System.out.println(secondsNano);
    System.out.println(secondsMili);
}

secondsNano will print something along the lines of 0.04, whereas secondsMili will print something very close to 1.

It looks like a bug along this line has been reported at Sun's bug database, but they closed it as a duplicate, but their link doesn't go to an existing bug. It seems to be very system-specific, so I'm getting more and more sure this is a hardware issue.

Answer 1

... he was using a System.nanotime to cause the program to wait before doing something, and ...

Can you show us some code that demonstrates exactly what he was doing? Was it some strange kind of busy loop, like this:

long t = System.nanoTime() + 1000000000L;
while (System.nanoTime() < t) { /* do nothing */ }

If yes, then that's not the right way to make your program pause for a while. Use Thread.sleep(...) instead to make the program wait for a specified number of milliseconds.

Answer 2

You do realise that the loop you are using doesn't take exactly 1 second to run? Firstly Thread.sleep() isn't guaranteed to be accurate, and the rest of the code in the loop does take some time to execute (Both nanoTime() and currentTimeMillis() actually can be quite slow depending on the underlying implementation). Secondly, System.currentTimeMillis() is not guaranteed to be accurate either (it only updates every 50ms on some operating system and hardware combinations). You also mention it being inaccurate to 40-50ms above and then go on to say 0.004s which is actually only 4ms.

I would recommend you change your System.out.println() to be:

System.out.println(secondsNano - secondsMili);

This way, you'll be able to see how much the two clocks differ on a second-by-second basis. I left it running for about 12 hours on my laptop and it was out by 1.46 seconds (fast, not slow). This shows that there is some drift in the two clocks.

I would think that the currentTimeMillis() method provides a more accurate time over a large period of time, yet nanoTime() has a greater resolution and is good for timing code or providing sub-millisecond timing over short time periods.

Answer 3

I've experienced the same problem. Except in my case, it is more pronounced.

With this simple program:

public class test {
    public static void main(String[] args) {
        while (true) {
            try { 
                Thread.sleep(1000); 
            } 
            catch (InterruptedException e) { 
            }

            OStream.out("\t" + System.currentTimeMillis() + "\t" + nanoTimeMillis());
        }
    }

    static long nanoTimeMillis() {
        return Math.round(System.nanoTime() / 1000000.0);
    }
}

I get the following results:

13:05:16:380 main:  1288199116375   61530042
13:05:16:764 main:  1288199117375   61530438
13:05:17:134 main:  1288199118375   61530808
13:05:17:510 main:  1288199119375   61531183
13:05:17:886 main:  1288199120375   61531559

The nanoTime is showing only ~400ms elapsed for each second.