ScheduledExecutorService behaving unexpectedly

Question

I have the following code snippet, using a ScheduledExecutorService to run every 3'000 milliseconds a check whether it should call a function onOutTimeout() or not. At least that's the idea.

 private void launchOutTimeoutChecker(){
    Runnable check = new Runnable() {
        @Override
        public void run() {
            float bonus = 0;
            if(firstOutTime){bonus = timeout_initial_bonus;}
            float temp = System.currentTimeMillis() - lastOutTime;
            if(temp < timeout + bonus){
                if(Debug.logKeepalivePackets){
                    Log.d("keepalive", "firstOutTime: "+firstOutTime+"\ntime passed: "+temp);
                }
                // don't timeout yet, launch new execution
                launchOutTimeoutChecker(); // yey recursion?!
            } else {
                if(Debug.logKeepalivePackets){
                    Log.d("keepalive", "TIMEOUT!\nfirstOutTime: "+firstOutTime+"\ntime passed: "+temp);
                }
                onOutTimeout();
            }
        }
    };

    // before the first message, give a bonus of timeout_initial_bonus
    long bonus = 0;
    if(firstOutTime){bonus = timeout_initial_bonus;}
    long time_out = bonus + timeout;
    futureOut = executorOut.schedule(check, time_out, TimeUnit.MILLISECONDS);

    // the task is now scheduled. after the timeout will it check whether it should actually trigger a timeout.
    // the ScheduledFuture could be used to cancel this again
}

Edit: where I set lastOutTime is in the run method of my (runnable) class. The method lastInTimeoutChecker does not print anything.

    @Override
public void run() {
    // initialize executors that are used in launchOutTimeoutChecker and launchInTimeoutChecker
    executorIn = Executors.newSingleThreadScheduledExecutor();
    executorOut = Executors.newSingleThreadScheduledExecutor();

    // start the timers in new threads
    this.lastOutTime = System.currentTimeMillis();
    launchOutTimeoutChecker();
    this.lastInTime = System.currentTimeMillis();
    launchInTimeoutChecker();

}

I would expect every 3 seconds to see a log message, because timeout is set to 3, and indeed the log message comes about every 3 seconds. But why is this output saying that the time passed is 0.0?

12-03 20:16:51.049 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                          time passed: 0.0
12-03 20:16:54.051 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                          time passed: 0.0
12-03 20:16:57.052 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                          time passed: 0.0
12-03 20:17:00.054 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                          time passed: 0.0
12-03 20:17:03.055 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                          time passed: 0.0
12-03 20:17:06.056 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                          time passed: 0.0
12-03 20:17:09.057 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                          time passed: 0.0
12-03 20:17:12.058 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                          time passed: 0.0
12-03 20:17:15.059 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                          time passed: 0.0
12-03 20:17:18.060 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                          time passed: 0.0
12-03 20:17:21.061 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                          time passed: 0.0
12-03 20:17:24.062 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                          time passed: 0.0
12-03 20:17:27.064 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                          time passed: 0.0
12-03 20:17:30.067 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                          time passed: 0.0
12-03 20:17:33.068 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                          time passed: 0.0
12-03 20:17:36.071 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                          time passed: 0.0
12-03 20:17:39.072 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                          time passed: 0.0
12-03 20:17:42.074 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                          time passed: 0.0
12-03 20:17:45.076 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: TIMEOUT!
                                                                          firstOutTime: false
                                                                          time passed: 131072.0

After about a minute, there is finally the message of a timeout, which I would have expected as the first log message. The number of time passed it says there is always exactly 131072 ms.

I don't understand at all how I could go about debugging this. What I did:

• made sure only one instance of the surrounding class was running. Didn't change much (except that the output was now as you see it, instead of every message being duplicated, but otherwise everything was the same)

• made sure lastOutTime is only set once, right before calling launchOutTimeoutChecker() for the first time, setting it to System.currentTimeMillis()

• firstOutTime is always false currently, so that part should be irrelevant

• At first, it worked as expected. Then I ran the same code in debug mode and this happened. Now the output as above also happens when I press the usual run.

• Rebuilding did not fix it

• Running it on a real device instead of the emulator exhibits the same behaviour.

• There doesn't seem to be a notable change in CPU usage or memory usage

What is wrong with my code?

Answer 1

Try not to use float for milliseconds. System.currentTimeMillis() returns a long and that's probably what's causing the trouble for you.

Answer 2

If I understood your requirements well, you want to schedule a task that will check some condition in a fixed rate to know if you should call some function named onOutTimeout. Here is a simple solution for this requirement:

  private long timeWhenYouShouldCallYourFunction;
  private ScheduledExecutorService service;

  private void launchOutTimeoutChecker() {
    Runnable check = new Runnable() {
      @Override
      public void run() {
        long currentTime = System.currentTimeMillis();
        System.out.println("ping " + currentTime);
        if (currentTime > timeWhenYouShouldCallYourFunction) {
          onOutTimeout();
          service.shutdown();
        }
      }
    };

    int randomShift = Math.abs(new Random().nextInt() % 10_000);
    System.out.println("Shift is " + randomShift + " msec");
    timeWhenYouShouldCallYourFunction = System.currentTimeMillis() + randomShift;
    service = Executors.newSingleThreadScheduledExecutor();
    service.scheduleAtFixedRate(check, 0, 3000, TimeUnit.MILLISECONDS);
  }

  private void onOutTimeout() {
    System.out.println("Made it!");
  }