java - ScheduledExecutorService 行为异常

Question

我有以下代码 fragment ，使用 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 的地方是在我的(可运行)类的运行方法中。 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 毫秒。

我完全不明白如何调试它。我做了什么:

• 确保只有周围类的一个实例在运行。没有太大变化(除了输出现在如您所见，而不是每条消息都被复制，但其他一切都是一样的)

• 确保 lastOutTime 只设置一次，就在第一次调用 launchOutTimeoutChecker() 之前，将其设置为 System.currentTimeMillis()

• firstOutTime 当前始终为 false，因此该部分应该无关紧要

• 起初，它按预期工作。然后我在 Debug模式下运行相同的代码，这发生了。现在，当我按通常的运行时，也会出现上面的输出。

• 重建没有解决它

• 在真实设备而不是模拟器上运行它会表现出相同的行为。

• CPU 使用率或内存使用率似乎没有显着变化

我的代码有什么问题？

Answer 1

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