読者です 読者をやめる 読者になる 読者になる

nishio-dens's diary

Railsとかプログラミング関連の備忘録

JavaにおけるTimer, ScheduledExecutorServiceのシステム時刻変更時の挙動の問題

問題点

  • java.util.Timer, java.util.concurrent.ScheduledExecutorServiceで処理を実行中にシステム時刻の変更を行うと、処理が不安定になる

実験環境

  • 実験環境1 - Ubuntu11.10 (OpenJDK)
    • Java version: java version "1.6.0_23" OpenJDK Runtime Environment (IcedTea6 1.11pre) (6b23~pre11-0ubuntu1.11.10) OpenJDK Server VM (build 20.0-b11, mixed mode)
  • 実験環境2 - MacOSX 10.6 (SunJava)
    • Java version: java version "1.6.0_26" Java(TM) SE Runtime Environment (build 1.6.0_26-b03-384-10M3425) Java HotSpot(TM) 64-Bit Server VM (build 20.1-b02-384, mixed mode)
  • 実験環境3 - Windows7 (SunJava)
    • Java version: java version "1.6.0_26" Java(TM) SE Runtime Environment (build 1.6.0_26-b03) Java HotSpot(TM) Client VM (build 20.1-b02, mixed mode, sharing)

周期的処理実行クラスのシステム時刻変更時の挙動の問題

デスクトップアプリケーション作成の際に、ScheduledExecutorServiceのバグに気がついたのでこのメモを残しておきます。

Javaで周期的に処理を実行したい場合、java.util.Timerやjava.util.concurrent.ScheduledExecutorServiceを利用します。しかしこのクラス、処理中にシステム時刻が変更されると、極めて不可解な動作を起こすので注意が必要です。

システム時刻が変更されるなんてこと、そうそうないだろうと思うかもしれませんが、実は結構頻繁に発生します。一番よくあるのが、コンピュータをスリープ状態にして復帰した場合です。

10分間PCをスリープしてから復帰した場合、システム時刻は10分進められます。また、最近のOSではNTPを用いた時刻同期が標準機能として搭載されています。これらの機能を用いた場合も、プログラム側から見た場合には時刻が進んだり、戻ったりしたように見えます。

時刻が修正された際に起こる不可解な挙動について検証してみます。今回は1秒周期でプログラム実行後の経過時間と現在時刻を表示するプログラムを用意します。

import java.util.Date;
import java.util.Timer;
import java.util.TimerTask;

public class TimerCheck {
    private class TestTask extends TimerTask{
        @Override
            public void run() {
            time++;
            System.out.println(time + " : " + (new Date()));
        }
        private long time = 0; //経過時間
    }
    public static void main(String[] args) {
        new TimerCheck().main2();
    }
    public void main2() {
        Timer timer = new Timer();
        timer.schedule(new TestTask(), 0, 1000);
    }
}

次に時刻が修正された場合の動作を検証します。今回はプログラム実行中に時刻を1分進め、その後1分戻すという手順を踏んでみます。結果は以下のようになりました。

実行結果
1 : Tue Nov 29 18:45:29 JST 2011
2 : Tue Nov 29 18:45:30 JST 2011
(略)
17 : Tue Nov 29 18:45:45 JST 2011
18 : Tue Nov 29 18:46:37 JST 2011 ← 1分時刻を進めた
19 : Tue Nov 29 18:46:38 JST 2011
20 : Tue Nov 29 18:46:39 JST 2011
(略)
28 : Tue Nov 29 18:46:47 JST 2011
29 : Tue Nov 29 18:46:48 JST 2011
                                  ← 1分時刻を戻したら、処理が止まった!

実験環境1,2,3ともに同様の結果となりました。1分時刻を進めた場合は問題なく動作していますが、1分時刻を戻した場合は動作が止まってしまいました。
私が望んでいる動作は、システム時刻にかかわらず1秒周期で処理を実行して欲しいのですが、予想外の結果です。

周期的にに処理を実行するクラスは、Timerの他にScheduledExecutorServiceが存在しています。

このクラスはJava5.0から導入された新しいクラスであり、現在ではTimerよりもこちらのクラスが推奨されています。上記と同様のプログラムをScheduledExecutorServiceを使って書きなおしてみます。

import java.util.Date;
import java.util.concurrent.Executors;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.TimeUnit;

public class ScheduledExecutorTest {
	private class TestTask implements Runnable{
		@Override
		public void run() {
			time++;
			System.out.println(time + " : " + (new Date()));
		}
		private long time = 0; //経過時間
	}
	public static void main(String[] args) {
		new ScheduledExecutorTest().main2();
	}
	public void main2() {
		ScheduledExecutorService scheduler = Executors.newSingleThreadScheduledExecutor();
		scheduler.scheduleAtFixedRate(new TestTask(), 0, 1000, TimeUnit.MILLISECONDS);
	}
}

Timerクラスを用いた場合と同様に、1分時刻を途中で進め、その後1分戻す動作を行ってみます。
結果が環境1,2,3それぞれ異なるので順番に書いていきます。

まず環境1(Ubuntu)での動作結果です。

1 : Tue Nov 29 18:27:18 JST 2011
2 : Tue Nov 29 18:27:19 JST 2011
(略)
21 : Tue Nov 29 18:27:38 JST 2011
22 : Tue Nov 29 18:27:39 JST 2011
23 : Tue Nov 29 18:28:29 JST 2011 ← 1分進めた
24 : Tue Nov 29 18:28:30 JST 2011
(略)
44 : Tue Nov 29 18:28:50 JST 2011
45 : Tue Nov 29 18:27:42 JST 2011 ← 1分戻した
46 : Tue Nov 29 18:27:43 JST 2011
47 : Tue Nov 29 18:27:44 JST 2011

期待通りの動作をしているようです。

次に実験環境2(MacOSX)で動作させてみます。

1 : Tue Nov 29 18:49:21 JST 2011
2 : Tue Nov 29 18:49:22 JST 2011
(略)
22 : Tue Nov 29 18:49:42 JST 2011
23 : Tue Nov 29 18:50:38 JST 2011 ← 1分時間を進めた
24 : Tue Nov 29 18:50:38 JST 2011  ← 24から78までの処理において、同時刻に同じ処理を一度に行っている
25 : Tue Nov 29 18:50:38 JST 2011
(略)
76 : Tue Nov 29 18:50:38 JST 2011
77 : Tue Nov 29 18:50:38 JST 2011
78 : Tue Nov 29 18:50:38 JST 2011
79 : Tue Nov 29 18:50:39 JST 2011
80 : Tue Nov 29 18:50:40 JST 2011
81 : Tue Nov 29 18:50:41 JST 2011
82 : Tue Nov 29 18:50:42 JST 2011
83 : Tue Nov 29 18:50:43 JST 2011
84 : Tue Nov 29 18:50:44 JST 2011
85 : Tue Nov 29 18:50:45 JST 2011
86 : Tue Nov 29 18:50:46 JST 2011
                                   ← 1分戻したら、処理が止まった!


これはとんでもない結果となってしまいました。
まず、時間を1分進めた場合、今まで実行できなかった処理(1分分の処理)を一気に実行しようとします。また時刻を1分戻した場合は、処理が停止してしまいました。

この問題は私がNishio Tweet Manager(NTM)というTwitterクライアントを作成中に気がつきました。NTMでは、60秒に1回ツイッターに対してタイムライン取得要求を出しているのですが、システムがスリープから復帰後、突然ツイッターに向けて猛烈な勢いでアクセスし始め焦りました。

最後に実験環境3の場合ですが、実行結果は省略させていただきます。
結果としては、1分時間を進めた際は問題ありませんでしたが、1分時間を戻すと処理が停止してしまいました。

まとめ

java.util.Timer利用時、システム内部時刻を1分進めた場合
実験環境 動作
環境1: Ubuntu 正常に動作
環境2: MacOSX 正常に動作
環境3: Windows7 正常に動作
java.util.Timer利用時、システム内部時刻を1分戻した場合
実験環境 動作
環境1: Ubuntu 処理が止まってしまう
環境2: MacOSX 処理が止まってしまう
環境3: Windows7 処理が止まってしまう
java.util.concurrent.ScheduledExecutorService利用時、システム内部時刻を1分進めた場合
実験環境 動作
環境1: Ubuntu 正常に動作
環境2: MacOSX 1分間に行われるはずであった処理を一度に処理する
環境3: Windows7 正常に動作
java.util.concurrent.ScheduledExecutorService利用時、システム内部時刻を1分戻した場合
実験環境 動作
環境1: Ubuntu 正常に動作
環境2: MacOSX 処理が止まってしまう
環境3: Windows7 処理が止まってしまう

この問題に関する詳しい知識をお持ちの方がいらっしゃいましたら、ご教示いただけるとありがたいです。