Javaパフォーマンス計測そんなタイマーで大丈夫か？

駄目だ。大問題だ。

long t1 = System.currentTimeMillis();
long t2 = System.currentTimeMillis();
System.out.println(t2-t1);

結果はなんとでるか？ 99.9%以上の確率で0が表示される。そもそもSystem.currentTimeMillis()は時刻をミリ秒で返す。1行のプログラムを実行するのに1ミリ秒もかかってたら、たかだか1000行分動いただけで1秒かかってしまう。今のコンピュータはそんなに遅くない。

そもそもドキュメントをちゃんと読むと

ミリ秒で表される現在の時間を返します。戻り値の時間単位はミリ秒ですが、値の粒度は基本となるオペレーティングシステムによって異なり、単位がより大きくなる場合があります。たとえば、多くのオペレーティングシステムでは、時間を 10 ミリ秒の単位で計測します。
Oracle Technology Network for Java Developers | Oracle Technology Network | Oracle

と、OSによって変わることと、その多くが10m秒程度の単位で計測することが書かれている。これじゃろくに測定できない。

そこでSystem.nanoTime()の登場である。Java5から使えるこのメソッドは

利用可能でもっとも正確なシステムタイマーの現在の値をナノ秒単位で返します。
このメソッドは、経過時間を測定するためだけに使用できます。システムのほかの概念や壁時計の時刻に関連していません。返される値は、固定された任意の時間からの経過時間 (ナノ秒) です。将来的に、値が負の数になる可能性があります。このメソッドは、ナノ秒単位の精度を提供しますが、必ずしもナノ秒の正確度ではありません。値の変更頻度は保証されません。約 292 年 (263 ナノ秒 ) を超える連続した呼び出しの差異では、数値のオーバーフローにより経過時間が正しく計算されません。
たとえば、一部のコードで実行にかかる時間を測定するには、次のようになります。
long startTime = System.nanoTime();
// ... the code being measured ...
long estimatedTime = System.nanoTime() - startTime;
Oracle Technology Network for Java Developers | Oracle Technology Network | Oracle

と、格段に精度が上がってる。ただし、絶対時間は取れないので区間タイムを測るようなときしか使えない。

long t1 = System.nanoTime();
long t2 = System.nanoTime();
System.out.println(t2-t1);

さて、なんとでるか？私の手元の環境*1だと1676と出た。2μ秒弱である。0.002m秒だ。これじゃSystem.currentTimeMillis()では測れないわけだ。

System.currentTimeMillis()の分解能

ところで、そもそもSystem.currentTimeMillis()は実際のところ何ミリ秒で測れるのか？そこで連続してcurrentTimeMillis()を呼び、値が変わったタイミングで差分をとってみよう。

long[] t = new long[10];
long pre = System.currentTimeMillis();
for (int i=0,j=0; j<10; i++) {
	long time = System.currentTimeMillis();
	if (pre != time) {
		t[j++] = time-pre;
		i=0;
		pre = time;
	}
}
for (int i=0; i<10; i++) {
	System.out.println(t[i]);
}

さてなんとでるだろう？私の手元の環境(Vista 32bit)だと1が10個並んだ。が、1ではない数字が並んだ人もいるんじゃないだろうか。WindowsXPのとあるマシンでは15と16が出た。ドキュメントにあるとおりOSで差が出る。場合によっては1ミリ秒単位で計測できるが、そうでない場合は10ミリ秒程度の精度しかでない。単位がミリ秒だからといってミリ秒で測れていない場合がある。

Systemクラスのソースコードを見ると

public static native long currentTimeMillis();

と、native宣言されている。ここから先はネイティブの世界。VMの実装依存の世界でもある。

System.nanoTime()の分解能

さて、一方のnanoTime()はどうか。先ほどの

long t1 = System.nanoTime();
long t2 = System.nanoTime();
System.out.println(t2-t1);

では、計測するたびに値がばらつく。だが何度か実行するとなにやら同じ値が何度か出ているように見える。

そこで1000回ぐらい値をとってグラフにしてみよう。横軸がナノ秒、縦軸が出現回数だ。

long[] t1 = new long[1001];
for (int i=0; i<1001; i++) {
	t1[i] = System.nanoTime();
}
long[] t2 = new long[1000];
for (int i=0; i<1000; i++) {
	t2[i] = t1[i+1]-t1[i];
	System.out.println(t2[i]);
}
final TreeMap<Integer, Integer> map = new TreeMap<Integer, Integer>();
for (long t : t2) {
	int ti = (int)t;
	Integer val = map.get(ti);
	if (val == null) val = 0;
	map.put(ti, val+1);
}
JFrame frame = new JFrame("nanoTime()分布");
frame.setDefaultCloseOperation(JFrame.EXIT_ON_CLOSE);
frame.setSize(800, 150);
JPanel panel = new JPanel() {
	private static final long serialVersionUID = 1L;
	@Override
	protected void paintComponent(Graphics g) {
		super.paintComponent(g);
		g.setColor(Color.BLACK);
		for (Entry<Integer, Integer> entry : map.entrySet()) {
			int x = entry.getKey()-1000;
			int y = entry.getValue();
			g.drawLine(x, 100-y, x, 100);
		}
	}
};
frame.getContentPane().add(panel);
frame.setVisible(true);

で、結果がコレ。

なんというか、飛び飛びの値が出ましたな。これがnanoTime()の分解能だ。手元の環境だと70n秒。別のXP機では270n秒ぐらいだった。これもハードやOSといったもので差が出る。

計測誤差

さてさて。手元の環境ではnanoTime()の分解能は70n秒程度だが、System.nanoTime()そのものに1327n秒とかかかってるわけである。そもそもこの1327というのは手元の環境での中央値だが、わりとバラつきもある。タイマーそのものに誤差を含むわけだから、計測結果を扱う際には注意が必要だ。

F1のタイムを手でストップウォッチで測ったらどうなるだろう？一般的なストップウォッチは0.01秒まで桁があるが、そもそも人間の手は0.01秒なんて正確さでボタンを押すことができない。じゃぁ0.01までの桁があるからと言ってその数字を正確な数字と思うわけにはいかない。工学系学生なら学生実験で嫌というほど教官に指導された有効数字ってやつだ。

nanoTime()の計測そのものに1000n秒=1μ秒ぐらいかかる以上、計測値として有効なのはμ秒の桁がいいところだ。それを考えずにパフォーマンス計測をして数字をイジってドヤ顔してるとボコボコにされかねない。

SIerは誤差とか考慮せずにステップ数とかから基準値算出してドヤ顔してるようなExcel職人が跋扈するような世界だが、めげずに頑張って欲しい。

*1:Panasonic CF-Y7を使っている。2008年夏モデル、つまり3年ぐらい前のノートPCというわけだ。細かいスペックはメーカーページ参照