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:

Any expectation?

I didn't get the same result as you, I got `2, 1000, 999, 1000, ...`. This was using jdk1.6.0_25. — Mark Peters, Sep 01 '11 at 12:36
I have noticed I have the same issue for a Swing animation. However, Timer is as erratic as ScheduledThreadPools and my results are even worse than yours, with many dt = 0. My guess is that it has to do with the processor. I have a 5 year old Core Duo 2 and Java 7. — toto2, Sep 01 '11 at 13:32
I'm on XP 64 bits and tested with jdk1.6.0_16 (64 and 32 bits) and jdk1.6.0_27 with same erratic results. My CPU is an intel core duo E8500 à 3.16GHz. — domak, Sep 01 '11 at 15:27
I also tested this on a linux, with expected results (better precision with ScheduledThreadPool than timer). I don't know if it's a OS or CPU problem. — domak, Sep 01 '11 at 16:36
By the way: As `last` is accessed from different threads (the main thread and the scheduled thread), you should declare it volatile. Otherwise, Java does not guarantee that one thread sees the value written by another. — FrankPl, Mar 28 '13 at 18:04

score 2 · Answer 1 · edited May 23 '17 at 12:04

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?

As I mentioned above in the comments, currentTimeMillis is as bad on my system. I looked at the api of both functions and they warn about having no guarantee of accuracy. — toto2, Sep 02 '11 at 12:08

scheduledThreadPool.scheduleAtFixedRate() strange behaviour

1 Answers1