JavaにおけるTimer, ScheduledExecutorServiceのシステム時刻変更時の挙動の問題
周期的処理実行クラスのシステム時刻変更時の挙動の問題
デスクトップアプリケーション作成の際に、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分時間を戻すと処理が停止してしまいました。