Java用爆速タイマーを作ってみる

（最終更新: 2011/03/06） # 履歴は記事の末尾にあります

先日、JDKのコードを読んで、JavaのSystem.nanoTime()を実行すると、Win32APIのQueryPerformanceCounterが使用されることを確認しました。

そこで、System.nanoTime()を使うよりも速いJava用タイマーを作ってみようと思います。

合言葉は、「そんなタイマーで大丈夫か?」「一番いいのを頼む」（※ただしインテルに限る）

何を考えたか

QueryPerformanceCounterは、マシン起動時からの秒数を取得します。であるならば、Javaからネイティブコードを呼び出し、インラインアセンブラに同じ処理を書いて実行することで、JDKを経由してWin32APIを叩く分のコストを削れると考えました。

さらに、手作りタイマーの良さを生かせば、次のコストを切り分けることができます。

• Javaからネイティブコードを使用する平均時間
• アセンブラ命令の平均実行時間

これらを測定結果から減じれば、より正確な時間計測ができるでしょう。たぶん、きっと、おそらく…。

とりあえず、やってみましょう。

タイマーの外観

Javaで定義するTimerクラスです。ネイティブメソッドを2つ宣言しています。

package inteltimer;

public class Timer {

    public static native void start();

    public static native long stop();

}

戻り値の非対称性が気持ち悪いと思われるかもしれませんが、これには理由があります。

当初、次のような実装を考えました。

1. 開始時点のカウンタを取得して、Javaの変数に代入する
2. 測定対象のJavaコードを実行する
3. 終了時点のカウンタを取得して、Javaの変数に代入する
4. Java上で、3から1を減じて、1/マシン周波数を乗じる

しかし、上の方法では、測定結果に開始時点のカウンタ値を戻す時間が加わります。また、（測定対象の処理時間には影響しませんが）Java側で引き算をするコストも発生します。目指すは爆速タイマーなので、そういうことは極力避けたいです。そのため、ネイティブ側のコードで開始カウンタを保持し、終了カウンタの取得前に回収して、アセンブラで引き算まで終わらせてからJavaに戻ってくることにしました。

その結果、start()に戻り値がありません。

ネイティブコード

javahを使って、ネイティブコードのヘッダファイルを生成します。

# そういえば、javaコマンドのオプションではclasspathをcpと書けるのに、なぜjavahではダメなんでしょう?

javah -classpath {Timerクラスのパッケージルートパス} -d {ヘッダファイルの出力先へのパス} inteltimer.Timer

上のコマンドを叩くと、次のファイルができます。

inteltimer_Timer.h

/* DO NOT EDIT THIS FILE - it is machine generated */
#include <jni.h>
/* Header for class inteltimer_Timer */

#ifndef _Included_inteltimer_Timer
#define _Included_inteltimer_Timer
#ifdef __cplusplus
extern "C" {
#endif
/*
 * Class:     inteltimer_Timer
 * Method:    start
 * Signature: ()V
 */
JNIEXPORT void JNICALL Java_inteltimer_Timer_start
  (JNIEnv *, jclass);

/*
 * Class:     inteltimer_Timer
 * Method:    stop
 * Signature: ()J
 */
JNIEXPORT jlong JNICALL Java_inteltimer_Timer_stop
  (JNIEnv *, jclass);

#ifdef __cplusplus
}
#endif
#endif

このヘッダファイルにある2つのネイティブメソッド、Java_inteltimer_Timer_startとJava_inteltimer_Timer_stopが含まれるネイティブコードを作成します。

inteltimer_Timer.cpp

#include <Windows.h>
#include "inteltimer_Timer.h"

unsigned long start_high;
unsigned long start_low;

JNIEXPORT void JNICALL Java_inteltimer_Timer_start
    (JNIEnv *env, jclass jclass){
	
	HANDLE hProcess = GetCurrentProcess();
	SetPriorityClass(hProcess, REALTIME_PRIORITY_CLASS); // (1)

	start_high = 0;
	start_low = 0;
	unsigned long time;

	__asm{
		sub eax, eax ; (2)
		sub edx, edx
		rdtsc ; (3)
		mov start_low, eax
		mov start_high, edx
	}
}

JNIEXPORT jlong JNICALL Java_inteltimer_Timer_stop
    (JNIEnv *env, jclass jclass){

	HANDLE hProcess = GetCurrentProcess();
	SetPriorityClass(hProcess, REALTIME_PRIORITY_CLASS);
	
	unsigned long time_high;
	unsigned long time_low;

	__asm{
		sub eax, eax
		sub edx, edx
		rdtsc
		sub eax, start_low
		sbb edx, start_high
		mov time_low, eax
		mov time_high, edx
	}

	SetPriorityClass(hProcess, NORMAL_PRIORITY_CLASS);
	
	return time_high == 0 ? time_low : 0; // (4)
}

何をやっているのか説明します。考え方や実装の誤りに気づかれたら、ぜひ教えてください。

(1) プロセスの優先度を最高にする

計測中、他の処理によってOSに割り込みが発生することがあります。この場合、CPUが計測対象のコードを実行することに使われていない間も、プロセッサのカウンタはどんどん進んでしまいます。これはよろしくありません。計測中は、マシンのCPUが計測対象のコードを実行することに集中している状態を保ちたいです。

そこで、SetPriorityClass関数を使用して、引数にREALTIME_PRIORITY_CLASSを与えることで、タイマーを実行するプロセスの優先度を他のすべてのプロセスよりも上にします。そして、計測が終わったら、引数にNORMAL_PRIORITY_CLASSを与え、優先度を元に戻します。

• Windows previous versions documentation | Microsoft Docs

この処理は、次のページで配布されている「Test programs for measuring clock cycles and performance monitoring」のコードを読んで、必要性に気づいたので追加しました。

• Software optimization resources. C++ and assembly. Windows, Linux, BSD, Mac OS X

(2) EAX、EDXのリセット

(3)のrdtsc命令の結果が格納されるEAX、EDXレジスタを、使用前にリセットします。レジスタの値を0にするには、レジスタ同士で計算をするのが一番速いらしいので、引き算を使います。

• CPUID命令によるCPUの性能・機能の把握 (1/2)：CodeZine（コードジン）: 「コラム：レジスタを0にする様々な手法」参照

(3) rdtsc命令

クロック回数を得るために、rdtsc命令を使用します。

Pentium以降のx86プロセッサには、Time-Stamp Counterというクロックサイクルごとにインクリメントされるカウンタがあります。この値を読み取るのがrdtsc(read time-stamp counter)命令です。

経過時間を扱うには、計測対象の処理の前後で、カウンタの値を取得します。終了時のカウンタ数から開始時のカウンタ数を引けば、計測対象の処理を実行している間に進んだカウンタ値が分かります。これをマシンの周波数で割って、処理にかかった秒数を得るわけです。

rdtscの戻り値は、上位32bitがEDXレジスタ、下位32bitがEAXレジスタに格納されます。

(4) 測定時間内に進んだカウンタ値を返す

上記のようにrdtscの戻り値が格納されるので、測定中のカウンタ数を得るために次の計算をしています。

1. 終了時カウンタの下位ビットから、開始時カウンタの下位ビットを引く
2. 終了時カウンタの上位ビットから、開始時カウンタの上位ビットを（切り下げを考慮して）引く
3. 下位ビットの引き算だけで済ませたいので、切り下げが起きていれば0を返し、測定ミス扱いにする

ここが最も自信がない部分です。0が返ってきたら測り直すことにして、手を抜きました。だめですかね…。実際のところ、0はまだ返ってきてないですが…。

cpuidを使うか否か → 今回は使わない

先ほどのリンク先（Software optimization resources. C++ and assembly. Windows, Linux, BSD, Mac OS X）からダウンロードできるアセンブラコードでは、rdtsc命令の前にcpuid命令が書かれています。

        cpuid                     ; serialize
        rdtsc                     ; read time stamp counter into edx:eax

cpuid命令は様々な役割を持ち、実行時のEAXレジスタの値によって挙動が異なります。たとえば、EAXに0を入れておくと、CPUの情報を返してくれます。

そのcpuid命令がなぜここで使われているかというと、アウトオブオーダによる影響を抑えることを目的としているようです。

CPUは、最適化のために処理の順序を内部で変更することがあります。つまり、かならずしも記述したタイミングでrdtsc命令が実行されるとは限りません。それは困りますよね。そこで、勝手に順序を変更されることを避けるために、cpuid命令が実行されると、直前までのすべての命令が完了することが要求される（らしい）、という性質を利用しているようです。

次のPDFはrdtscに関する別の資料です。上のコードと同じく、rdtscの直前にcpuid命令を使用しており、理由としてそのようなことが書かれていました。

• Using the RDTSC Instruction for Performance Monitoring (PDF)

この話は一見もっともらしいのですが、、、しかし、cpuidの最新のマニュアルには、そのような動作に関する言及がありません。（まだ精読していないので、見落としている可能性はありますが）

• Intel Processor Identification and the CPUID Instruction (PDF)

さらに、「仕様化されていないcpuidの動作を当てにしたプログラミングをするな」という注意がいくつも書かれています。アウトオブオーダを回避する目的でcopuidを利用することが、これに当たるのではないか気になります（大丈夫なんだろうか?）。cpuidの動作の仕組みを理解するまでは、使用しないことにしました。

ただ、本来は、何らかの方法で命令の処理順序を制御することが望ましいのではないかと思います。今回は、その部分を実現できていないことになります。

タイマーの使い方

タイマーを呼び出すコードは、次のとおりです。

Main.java

package inteltimer;

public class Main {
    public static void main(String[] args) {
        System.loadLibrary("inteltimer_Timer");
        Timer.start();
            
        // 計測対象のJavaコード

        long time = Timer.stop();
        System.out.println(time);
    }

ここで、冒頭で挙げた2つのオーバーヘッドを計測し、必要に応じて削ることにします。この値はマシンに依存するので、測定環境ごとに計測する必要があります。

アセンブラ命令の平均実行時間

rdtsc命令の実行にかかる時間を計測してみます。ネイティブコードからrdtscを2回呼び出しています。このとき、Javaは使いません。また、他の処理も行いません。

#include <Windows.h>
#include <stdio.h>

int main(void){

	FILE *fp;
	char *file = "rdtsc.csv";
	fp = fopen(file, "w");
	if( fp == NULL ){
		return -1;
	}

	HANDLE hProcess = GetCurrentProcess();
	SetPriorityClass(hProcess, REALTIME_PRIORITY_CLASS);

	for(int i = 0; i < 3000; i++){
		unsigned long start_low;
		unsigned long start_high;
		unsigned long result_high;
		unsigned long result_low;

		__asm{
			sub eax, eax
			sub edx, edx
			rdtsc
			mov start_low, eax
			mov start_high, edx
			
			sub eax, eax
			sub edx, edx
			rdtsc
			sub eax, start_low
			sbb edx, start_high

			mov result_low, eax
			mov result_high, edx
		}
		fprintf(fp, "%u\n", result_high == 0 ? result_low : 0);
	}
	fclose(fp);
	return 0;
}

3000回実行し、次の結果を得ました。

-	最大値	最小値	平均	偏差
クロック数	72	64	66.128	3.436914

時間ではなくクロック数です。実行したマシンは2.13Ghzなので、たとえ最大値を採用しても、rdtsc命令には 3.38028169×(10^-8) 秒しかかかっていないことになります。単独では無視してよい数値だと思います。

Javaからネイティブコードを呼び出す平均時間（アセンブラ命令の実行時間を含む）

JNIの使用によるオーバーヘッドを計測します。

Javaから、間に何も挟まずにstartメソッドとstopメソッドを実行しました。コードはこんな感じです。Main.javaの時間計測部分をfor文で回して、CSVに書き出しているだけです。

• Google Code Archive - Long-term storage for Google Code Project Hosting.
• Google Code Archive - Long-term storage for Google Code Project Hosting.

# 記事公開後、計測を2回やり直しました。詳細は、記事末尾の修正履歴にあります。ここでは、最新の計測について記述します。（2011/03/06、追記）

起動時のオプションは次のとおりです。

java -cp . -server -XX:CompileThreshold=10000 -Djava.library.path={ネイティブコードのdllを配置したフォルダへのパス} -Xms1024m -Xmx1024m inteltimer.Main

閾値を10000としたので、今回は20000回実行し、次の結果を得ました。

-	最大値	最小値	平均	偏差
クロック数（正・3回目）	298744	36368	39387.20	5498.52
クロック数（誤・2回目）グラフ	497016	36008	45162.64	32352.65
クロック数（誤・1回目）グラフ	251744	36008	42107.32	20345.22

偏りがありますね。グラフにするとよく分かります。単純に平均値を取るのはまずいようです。

• x軸: 値−平均
• y軸: 1/(SQRT(2π)×標準偏差) × EXP（(-1)×(値-平均)）^2/(2×標準偏差^2)

（参考: Excelによる正規分布曲線のグラフの作り方 | ブログ | 統計WEB）

高頻度で取得できたデータの周囲をざっくり取って、JNIの呼び出しコストを大体 37552〜41600 クロックと考えることにしました。およそ 1.76300469×(10^-5) 〜 1.95305164×(10^-5) 秒、つまり、18〜20マイクロ秒です。

なお、時間を計る部分でrdtscを使用しているため、取得した値にはアセンブラ命令の実行時間が含まれてしまいます。より厳密にいうなら、アセンブラ命令の実行にかかった64〜72クロックを減じた値が、JNIの呼び出しコストになりますね。

というわけで、今回の測定環境でタイマーを使うには、取得したカウンタ値から 37552〜41600 クロックを減じてから、周波数で割ればよいことが分かりました。

まとめ(?)

一応、System.nanotime()よりも本当に速いかも検証したのですが、それはまた今度に。まずは、このタイマーが妥当かをはっきりさせるべきだと気づいて、冷静になってもうたです。。。

ええ、正直そんなに速くなってないんですヨネ…。いったいどうすれば、爆速に実行可能なタイマーが手に入るんだろう…?

今回使用したコードは、以下の場所にあります。

• Google Code Archive - Long-term storage for Google Code Project Hosting.

修正履歴

JNIコスト計測の実行回数、JVM種別、実行時オプションを変更、再計測 (2011/03/05)

当初、JNIコストを得るために時間計測処理を3000回実行していました。実行回数について、ブックマークコメントでsh2さんから指摘をいただきました。ありがとうございます。

Java側がHotSpotでネイティブコードに変換されることが考慮されていない。たった3,000回の最頻値ではなく、-server -XX:CompileThreshold=NでServer VMを使用しN回目以降の処理クロック数を計測結果とするべき。参考 http://www.ibm.com/developerworks/jp/java/library/j-jtp02225/

JITコンパイルが始まる繰り返し処理の閾値の話ですね。

最初の計測では、clientVMを使用し、CompileThresholdオプションは使用していませんでした。（繰り返し実行に依存する）最適化が開始される閾値が、clientVMの場合はデフォルトで1500なので、その倍ということで3000回実行しよう、というふうに考えていました。

がしかし、教えていただいたページをもとに改めて少し調べると、様々なJVMの最適化（それが何を指すのかをコードレベルで把握していませんが…）が、clientVMでは適用されないようです。取得値の集合に、最適化された結果の計測時間を混ぜるためには、serverVMを使用するべきでした。# あと、そもそも、計測環境のVM種類と実行時オプションについては、最初から文中で言及するべきでした。すみません。

というわけで、改めて測定しました。

JNIコストの再計測が間違っていたので再々計測 (2011/03/06)

上記の再計測を行った際、次のように書いていたのですが、

なお、再計測の結果には、最適化された実行結果が含まれているはずですが、どういうわけか、最初の計測結果よりも平均クロック数が増えています。これはまぁ最初の値がいい加減だったということかな、くらいに思っています。が、どうなんでしょうね。（2011/03/05、追記)

やはりおかしいと思って見直したところ、別の計測に使用していたSystem.nanoTime()の処理が含まれており（1行削除し忘れていた）、余計なコストがかかっていました。そのため、再々計測をしました。

また、値の変動の要因の1つには、もちろん、clientVMからserverVMに変えたこともあるでしょう。

コードリポジトリへのリンクを追加 (2011/03/06)

使用したコード一式へのリンクを文中に追加しました。

グラフのx軸、y軸の説明を補足 (2011/03/06)

JNIコスト計測の結果グラフについて、x軸とy軸の説明を追記しました。