ScheduleThreadPool.scheduleAtFixedRate () weird behavior

Question

I have this simple test:

import java.util.Timer; import java.util.TimerTask; public class ScheduleTest { private static long last; public static void main(String[] args) { last = System.currentTimeMillis(); Timer timer = new Timer(); timer.schedule(new TimerTask() { @Override public void run() { Long current = System.currentTimeMillis(); System.out.println(current - last); last = current; } }, 0, 1000); } } 

which give me the expected result:

0
1000
1000
1000

If you replace Timer with ScheduleThreadPoool, it gives me a strange result:

 import java.util.concurrent.Executors; import java.util.concurrent.ScheduledExecutorService; import java.util.concurrent.TimeUnit; public class ScheduleTest { private static long last; public static void main(String[] args) { last = System.currentTimeMillis(); ScheduledExecutorService scheduledThreadPool = Executors.newScheduledThreadPool(1); last = System.currentTimeMillis(); scheduledThreadPool.scheduleAtFixedRate(new Runnable() { @Override public void run() { Long current = System.currentTimeMillis(); System.out.println(current - last); last = current; } }, 0, 1000, TimeUnit.MILLISECONDS); } } 

Result:

 0 2359 2079 2312 1844 2266 

Any expectation?

Answer 1

I think I have a key.

ScheduledThreadPool uses DelayQueue to store the following tasks to run. DelayQueue uses System.nanoTime () to calculate the remaining time before the task starts.

But System.nanoTime () seems to be buggy on my PC (XP 64 SP2):

  while (true) { long start = System.currentTimeMillis(); long startNanos = System.nanoTime(); LockSupport.parkNanos(Thread.currentThread(), 1000000000); System.out.println("after: " + (System.currentTimeMillis() - start) + " - nanos: " + (System.nanoTime() - startNanos) + " - nanos converted: " + TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNanos)); } 

Results:

 after: 1000 - nanos: 499769959 - nanos converted: 500 after: 1000 - nanos: 415454114 - nanos converted: 415 after: 1000 - nanos: 416274224 - nanos converted: 416 after: 1000 - nanos: 416141257 - nanos converted: 416 after: 1000 - nanos: 418547153 - nanos converted: 418 

So the task redistribution is incorrect based on biaid nano. The timer uses System.currentTimeMillis (), which works well.

There are many discussions about System.nanoTimes ():

Is System.nanoTime () completely useless?

Why is my System.nanoTime () not working?