コードの時間測定

アプリケーションの開発のある段階で、最適化が必要になることがあります。そして、最適化の効果を測定するには、計測を行う必要があります。 "ストップウォッチを使う" というのは粗雑で不正確で、おまけに少々おバカな方法です。コンピュータの中には既に正確な時計があるのですから。ここでは、組み込みの時計の使い方を紹介します。

第一の方法は、プログラム全体の実行時間を測定することです。これは、「現在の時刻を記録して、引数で指定されたプログラムを実行して、終了時の時刻を記録して引き算する」という小さなシェルプログラムで実現できます：

import std.stdio;
import std.c.stdlib;
import std.date;
import std.process;

int main(char[][] args)
{	d_time starttime;
	int status;

	if (args.length < 2)
	{	writefln("Time execution of a command.\nUse:\n\ttimer command args...");
		std.c.stdlib.exit(1);
	}
	starttime = getUTCtime();
	status = spawnvp(0, args[1], args[1 .. length]);
	starttime = getUTCtime() - starttime;
	if (status == -1)
	{	writefln("'%s' failed to execute", args[1]);
		std.c.stdlib.exit(1);
	}
	writefln("Elapsed time = %d.%03d seconds",
		cast(int) (starttime / TicksPerSecond),
		cast(int) (starttime % TicksPerSecond));
	if (status != 0)
		writefln("--- errorlevel %d",status);
	return status;
}

この方法は、もちろん、全てを計測に含めてしまいます。プログラムのロード時間や、モジュール構築時間、破棄時間、その他の同時に処理されていたタスクの時間などなど。意味のある結果を得るためには、時間に影響を与えそうな他のプログラムは停止しておき、測定プログラムを何度も実行して結果が収束するのを待たねばなりません。

一部分のコードの時間を測定するのは、以下の三行のコードで示せるように、とてもシンプルです：

	d_time starttime = getUTCtime();
	{ ... 測定したいコード ... }
	d_time elapsedtime = getUTCtime() - starttime;

ですが、それでも面倒な作業です。もっと巧い方法として、 D のスコープ終端における auto デストラクト処理 (別名RAII - Resource Acquisition Is Initialization) を使う手があります：

import std.stdio;
import std.date;

class Timer
{
    static d_time getCount()
    {
	return getUTCtime();
    }

    d_time starttime;

    this() { starttime = getCount(); }
    ~this()
    {
	writefln("elapsed time = %s", getCount() - starttime);
    }
}

void main()
{
    auto Timer t = new Timer();

    for (int i = 0; i < 10000; i++)
    {
    }
}

この方法では、スコープ内のコードをの時間を測定するのに、たった一行だけコードを挿入すれば済んでいます。スコープを抜けると、デストラクタ内で経過時間が計算され、結果が表示されます。

これは確かに動作しますが、しばらく使ってみた後、おそらくまた別の問題に気づくでしょう。getUTCtime() は、時刻をミリ秒単位で返しますが、これは小さなコード片の時間を測定するには大雑把過ぎるのです。もっと問題なのは、この方法は時刻を得るのにOSを呼び出していることです。そのせいで、経過時間の総計に、未知のたぶんかなり大きな実行時間が足されてしまいます。

解決策は、Pentium以降のCPUに搭載された RDTSC (Read Time-Stamp Counter) 命令です。この命令はCPUのサイクル数を EDX:EAX に返すもので、プロファイル用途には完璧です。これを使うには、getCount をインラインアセンブラの魔法を使って書き直すだけです：

import std.stdio;

class Timer
{
    static long getCount()
    {
	asm
	{	naked	;
		rdtsc	;
		ret	;
	}
    }

    long starttime;

    this() { starttime = getCount(); }
    ~this()
    {
	writefln("elapsed time = %s", getCount() - starttime);
    }
}

void main()
{
    auto Timer t = new Timer();

    for (int i = 0; i < 10000; i++)
    {
    }
}

long 型は、関数からは EDX:EAX の形で返りますから、これで正しく動作します。これで、非常に高精度かつ、オーバーヘッドも非常に小さい安定したタイマーが手に入りました。

この方向でさらに高度化したタイマーは、std.perf に実装されています。

これらのタイマーは、選択したコードの部分を計測することしかしません。プログラム全体の操作を計測し、関数同士が何回呼び出され、ボトルネックがどこにあるのかを探し、様々な処理の時間計測を行うには、適切なプロファイラが必要です。幸いなことに、DMD には、 -gt コマンドラインスイッチとあわせて使えるプロファイラがあります。