scheduledThreadPool.scheduleAtFixedRate() strange behaviour

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 expected result:

0
1000
1000
1000

If I replace Timer by a ScheduleThreadPoool, it gives me weird 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 clue.

ScheduledThreadPool use a DelayQueue to store next tasks to launch. DelayQueue use System.nanoTime() to compute remaining time before task can be run.

But System.nanoTime() seems 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 replanification of task is not correct based on biaised nanos. Timer uses System.currentTimeMillis() that works well.

There are lots of discussions about System.nanoTimes():

Is System.nanoTime() completely useless?

Why is my System.nanoTime() broken?