ScheduledExecutorService出其不意

Question

下面的代码片段使用ScheduledExecutorService每3'000毫秒运行一次，检查是否应该调用函数onOutTimeout()。至少这是个主意。

 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
}

编辑:我将lastOutTime设置在我的(runnable)类的run方法中。lastInTimeoutChecker方法不打印任何内容。

    @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();

}

我预计每3秒钟就会看到一条日志消息，因为timeout设置为3，而且日志消息实际上是每3秒发出一次。但是为什么这个输出说时间过去了是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

大约一分钟后，终于有了超时的消息，我希望这是第一条日志消息。它说，在过去的时间里，一直都是，131072，ms。

我一点也不明白我怎么会去调试这个。我所做的：

• 确保只运行周围类的一个实例。没有发生太大的变化(除了现在的输出和您看到的一样，而不是每一条消息都被复制，但否则一切都是一样的)
• 确保lastOutTime只设置一次，在第一次调用launchOutTimeoutChecker()之前，将其设置为System.currentTimeMillis()
• firstOutTime当前总是错误的，所以这个部分应该是不相关的。
• 起初，它如预期的那样起作用。然后在调试模式下运行相同的代码，发生了这种情况。现在，像上面这样的输出在我按下通常的运行时也会发生。
• 重建并没有修复它
• 在真正的设备上而不是在模拟器上运行它，表现出相同的行为。
• CPU的使用和内存的使用似乎没有显著的变化

我的密码怎么了？

Answer 1

尝试在毫秒内不要使用float。System.currentTimeMillis()返回一个long，这可能是给您带来麻烦的原因。

Answer 2

如果我很好地理解了您的需求，那么您希望安排一个任务，该任务将以固定的速率检查某些条件，以了解是否应该调用某个名为onOutTimeout的函数。以下是此需求的简单解决方案：

  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!");
  }