VCのReleaseモードにおける時間計測の方法について

[てまりけっとおーぶ]

こんにちは、ネカと申します。

今回はVisualStudioのReleaseモードにおける時間計測の方法を知りたく質問させていただきました。


開発にはVisualStudio2013 , 言語はC++を利用しています。


まず初めに、一般的にプログラムの特定の処理時間を知りたい場合は、

コード:

int time = timeGetTime();
/*何らかの処理*/
time = timeGetTime() - time;

というように、時間計測関数を上下に挿入すると思います。


私も今まで処理時間を知りたいときはDebugモードの状態でいつもこの方法を使用してきました。
しかしDebugモードではなくReleaseモードで動かさなければ
実際のアプリケーション動作中での正確な処理時間が測れないのではないかと思い、Releaseモードに切り替えてみたところ、
特定の処理に置いては処理時間が常に0を示すような結果となりました。

以下に処理時間を図るソースコード[1] , 時間を図る対象となる処理A[2] , 時間を図る対象となる処理B[3]をお載せします。

処理時間を測るソースコード[1]

コード:

QueryPerformanceFrequency(&freq_pc);
QueryPerformanceCounter(&start_pc);
　　　　int count = 0;
	　　for(int i = 0; i < 10000000; i++){
		　/*任意の処理*/
                   FuncA(i); //(またはFuncB());
		}
QueryPerformanceCounter(&end_pc);
double millSec = (((double)end_pc.QuadPart - (double)start_pc.QuadPart) / (double)freq_pc.QuadPart) * 1000;

時間を測る対象となる処理A[2]

コード:

int FuncA(int i){

	int file   = 8 - (i % 9); //列
	int rank   = i / 9; //行

	return file * 9 + rank;

}

時間を測る対象となる処理B[3]

コード:

unsigned long FuncB(){

	static unsigned long x = 123456789;
	static unsigned long y = 362436069;
	static unsigned long z = 521288629;
	static unsigned long w = 88675123; 
        static unsigned long t = 0; 
        t = (x ^ (x << 11));
	x = y; 
	y = z;
	z = w; 
	return(w = (w^(w >> 19)) ^ (t^(t>>8))); 

}

[1]にてFuncA(i)を実行させた場合の処理時間は常に0.00となり、FuncB()に関しては正しい処理時間が計測できました。
以降は今回の原因を調べているときに気が付いたことになります。

・start_pc.QuadPart , end_pc.QuadPart , freq_pc.QuadPartの値も表示させてみたところ、0以外の数値を取得できていたため、
　QueryPerformanceFrequency(&freq_pc);とQueryPerformanceCounter(&start_pc);の関数は動作している。
　しかし、常にstart_pc.QuadPartとend_pc.QuadPartの値が一致しているため、FuncAの計測時間が0になる。

・最適化の関係でfor文の中身が実行されていないのではないかと思い、for文の中でcount変数をインクリメントしたところ、
　for文で回した数だけの値が出力されたため、for文内部をスキップしているわけではない。

・処理の実行時間はかなり短いが、１億ループ回して処理時間が1マイクロ秒以内に収まるとは考えられない。

・時間計測関数で、TimeGetTime()やclock()関数も用いてみたが、いずれもFuncAの計測時間が0.00となった。

長文になってしまい申し訳ありませんでしたが、まとめますと、
「Releaseモードでも正確な実行時間を取得できる方法」と「可能であれば今回のような問題が起こる原因も知りたい」ということです。
どうかご教授お願いします。

[てまりけっとおーぶ]

連投となってしまいご迷惑おかけします。
本スレッドを投稿する際に、「C言語交流フォーラム」に寄せられた過去スレッドの中から同じような内容の質問が無いかを
調べるべきでしたが、検索方法が分からず、誠に身勝手ながら過去スレッドを参照せずに投稿させていただきました。
本スレッドの内容とは別に、過去スレッドの検索方法を教えていただけませんでしょうか。よろしくお願いします。

[h2so5]

・最適化の関係でfor文の中身が実行されていないのではないかと思い、for文の中でcount変数をインクリメントしたところ、
　for文で回した数だけの値が出力されたため、for文内部をスキップしているわけではない。

そうとは限りませんよ。
Visual C++での出力は試していませんが gccで最適化をかけてコンパイルしたところ、ループ内部はすべてスキップされました。
最適化によって関数は呼び出されませんし、count変数には最初から10000000が設定されるのでループしているかのように見えるだけです。

[h2so5]

連投となってしまいご迷惑おかけします。
本スレッドを投稿する際に、「C言語交流フォーラム」に寄せられた過去スレッドの中から同じような内容の質問が無いかを
調べるべきでしたが、検索方法が分からず、誠に身勝手ながら過去スレッドを参照せずに投稿させていただきました。
本スレッドの内容とは別に、過去スレッドの検索方法を教えていただけませんでしょうか。よろしくお願いします。

ページの一番下に検索欄があります。

[sleep]

「Releaseモードでも正確な実行時間を取得できる方法」

FuncB同様、関数内で使用されている変数にstaticを付与するか、

コード:

int FuncA(int i){

	static int file = 8 - (i % 9); //列
	static int rank = i / 9; //行

	return file * 9 + rank;

}

もしくは、関数の結果を使用する状況を作れば、不要と判断されないはずです。

コード:

QueryPerformanceFrequency(&freq_pc);
QueryPerformanceCounter(&start_pc);
　　　　int result = 0;
　　　　int count = 0;
    　　for(int i = 0; i < 10000000; i++){
        　/*任意の処理*/
                   //FuncA(i);
                   result = FuncA(i);
                   //FuncB();
                   //result = FuncB();
        }
QueryPerformanceCounter(&end_pc);
double millSec = (((double)end_pc.QuadPart - (double)start_pc.QuadPart) / (double)freq_pc.QuadPart) * 1000;
std::cout << result << std::endl;

「可能であれば今回のような問題が起こる原因も知りたい」

h2so5さんがおっしゃっている通り、最適化により不要と判断され処理がスキップされています。
FuncBは、static変数への（他変数を使用した動的な計算を伴う）値の代入式が使用されているため
不要と判断されなかったのでしょう。
FuncBについてもstaticを外せば処理がスキップされるはずです。

あと、変数にstaticを付与した場合の最適化は（例を限定すると、関数の結果を使用してないケース）
static変数が関係する（他変数を使用した計算を伴うなど、つまり動的な）処理は残されるはずですが、
static変数が全く関わらない処理、またはstatic変数が関わっていたとしても静的な処理については、
同じ関数内の処理でも最適化によりスキップされる可能性があります。

完全に正しい答えを示すのはまず無理で、最適化の基準はコードの状況で変動するはずなので
その辺の判断基準はコンパイラ（とその最適化レベル）に依存すると思われます。

[てまりけっとおーぶ]

>>h2so5さん

回答ありがとうございます。
確かにcount変数のインクリメントがされているので時間測定対象の関数も実行していると思い込んでおりました。


h2so5さんの回答を元に、Visual Studioに最適化をオフにする設定を見つけ出し、実際にオフに切り替えたところ
確かに最適化したものと比べて実行時間は格段に大きくなりました。
このことから、関数が最適化されていたため実行されていなかったということが分かりました。

しかし、関数の最適化をオフにすることにより、やはり正味の実行時間より遅くなるような結果になってしまうため、私は以下の方法を考えました。

処理時間

コード:

static int gCallCounter = 0;
int FuncA(int i){
    gCallCounter++;　　　　　←　追加した一行
    /*関数の処理*/
}

グローバル変数を導入すれば、最適化によって関数を省略するわけにはいきませんので、
最適化の設定がされていても計測時間を取得することが出来ました。
しかし、厳密な処理時間を求めたい場合には（私が現在取り組んでいるプログラムもそうですが）
インクリメント処理一行が大きく響いてくる場合があると思います。
そのため時間計測の処理を次のように改善しました。

コード:

        ////////////////////////////////////////////////////
		//計測対象の処理
　　　　　////////////////////////////////////////////////////
		QueryPerformanceFrequency(&freq_pc);
		QueryPerformanceCounter(&start_pc);

		int list[100];
		for(int i = 0; i < 1000000; i++){
			FuncA(ptree);
		}

		QueryPerformanceCounter(&end_pc);
		double ProcessTime =  (((double)end_pc.QuadPart - (double)start_pc.QuadPart) / (double)freq_pc.QuadPart) * 1000;

		////////////////////////////////////////////////////
		//インクリメント単体の処理		
　　　　　////////////////////////////////////////////////////
		QueryPerformanceFrequency(&freq_pc);
		QueryPerformanceCounter(&start_pc);

		for(int i = 0; i < 1000000; i++){
			counter++;
		}
        double incrementTime =  (((double)end_pc.QuadPart - (double)start_pc.QuadPart) / (double)freq_pc.QuadPart) * 1000;

        double correctTime = processTime - incrementTime;

　　　　 printf("%d\n" , counter);

インクリメント単体での実行処理を引いてあげることで、correctTimeには正確なFuncA()の実行時間が格納されると思います。
最後のprintf文を省略すると、インクリメントしたcount変数をアウトプットする機会がないため、やはり最適化によって処理がスキップされてしまいました。
そのため、printf文を追加し、最適化を回避しました。

今回の一件を逆の立場から見て、今後は最適化されていない処理を最適化できる箇所がないかどうかを意識してみたいと思います。

また、次回以降は検索履歴を調べてから質問したいと思います。
それでは、改めて回答ありがとうございました。

[てまりけっとおーぶ]

>>sleepさん

回答ありがとうございます。
sleepさんの仰る通り、計算を行ったものの計算結果を利用される場所が無いのでは、最適化して計算処理を省いてしまっても
プログラム全体の処理は変わらないのですね。

もしくは、関数の結果を使用する状況を作れば、不要と判断されないはずです。

printf("%d" , counter);を追加したことでcounter++のインクリメント処理の最適化が回避されたので納得ができました

完全に正しい答えを示すのはまず無理で、最適化の基準はコードの状況で変動するはずなので

100万回ループさせた処理時間が1万回ループさせた処理時間の100倍になるとは限らない、という時点で完璧な正味時間を
求めるのは、やはり無理なのですね。

[h2so5]

インクリメント単体での実行処理を引いてあげることで、correctTimeには正確なFuncA()の実行時間が格納されると思います。

そんな単純な問題ではありません。C言語でのコードが同じだからといって出力されるコードも同じとは限らないからです。