System.nanotime is slow?

One of my friends showed me something that he did and it was really hard for me to explain how this could happen: he used System.nanotime to do something and every time he presented the user with an update tell how much time had passed (that's Thread.sleep (1000) for this part) and it took seemingly forever (what waited 10 seconds took about 3 minutes to complete). We tried to use millitime to find out how much time passed: it printed how many nanotypes passed every second, and we saw that for every second the nanotypes were moving about 40-50 milliseconds every second.

I checked for errors related to System.nanotime and Java, but it seems the only thing I could find was that the sudden appearance of nanotime increased significantly and then stopped . I also looked at this blog post based on what I read in another question, but that didn't have anything to trigger it.

Obviously, for this situation, this could be worked around by simply using a million instead; there are many workarounds for this, but I am wondering if there is something other than a hardware problem with the system clock, or at least the most accurate clock the processor has (since using System.nanotime) what can make it run as slow as 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 lines 0.04, whereas secondMili will print something very close to 1.

It looks like a bug on this line was logged in the Sun bug database , but they closed it as a duplicate, but their link does not go to the existing bug. This seems to be very system specific, so I am becoming more and more convinced that this is a hardware issue.

+2


source to share


3 answers


... he used System.nanotime to make the program wait before doing anything, and ...

Can you show us some code that shows exactly what it was doing? Was it some kind of weird kind of busy cycle like:



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

      

If so, then this is not the correct way to pause for a while. Use Thread.sleep(...)

instead to have the program wait a specified number of milliseconds.

+4


source


Do you understand that the loop you are using does not take exactly 1 second? First, Thread.sleep () is not guaranteed to be accurate, and the rest of the code in the loop takes some time to execute (both nanoTime () and currentTimeMillis () can actually be quite slow depending on the underlying implementation). Second, System.currentTimeMillis () is also not guaranteed to be accurate (it refreshes every 50ms on some operating systems and hardware combinations). You also indicate that it is inaccurate 40-50m. Above and then keep pronouncing 0.004s, which is actually only 4ms.

I would recommend that you change your System.out.println () like this:

System.out.println(secondsNano - secondsMili);

      



Thus, you will be able to see how the two hours differ from the second in time. I left it running for about 12 hours on my laptop and it was at 1.46 seconds (fast, not slow). This shows that there is some drift at two hours.

I would have thought the currentTimeMillis () method provides more accurate time over a long period of time, but nanoTime () has a higher resolution and is good for timing code or providing submillisecond time over short periods of time.

+3


source


I got the same problem. Except for 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

      

nanoTime only shows ~ 400ms elapsed every second.

+1


source







All Articles