c++ builder > 関数の処理時間チェック > C実装のソースを計測する  > v0.4 外部ファイル化 / v0.5 出力部分拡張

```txt:動作環境
C++ Builder XE4
```

http://qiita.com/7of9/items/b9dd65ca15cb7e9c3a53
の続き。

今後の再利用のため、処理を外部ファイルにした。

### code v0.4

```UtilMeasureProcTime.h
//---------------------------------------------------------------------------

#ifndef UtilMeasureProcTimeH
#define UtilMeasureProcTimeH

#include <System.hpp>

//---------------------------------------------------------------------------

/*
関数の処理時間の計測
*/

/*
以下のような場合、funcB, funcC, funcDを並列的に測定できる。
funcAとfuncBを同時測定するとfuncAの結果にオーバヘッドが生じる。

void funcA() {
   funcB();
   funcC();
   funcD();
}
*/

/*
使用例

void funcA() {

MEASURE_PROC_TIME_CHECK(
   funcB();
, L"funcB"
)

MEASURE_PROC_TIME_CHECK(
   funcC();
, L"funcC"
)

MEASURE_PROC_TIME_CHECK(
   funcD();
, L"funcD"
)

}


*/

// 測定対象関数で使うマクロ
#define MEASURE_PROC_TIME_CHECK(call,name)            \
{                                                     \
	MeasureProcTime_OnTrigger(name);                  \
	call                                              \
	MeasureProcTime_OffTrigger(name);                 \
}
//---------------------------------------------------------------------------

void __fastcall MeasureProcTime_OnTrigger(String funcname);
void __fastcall MeasureProcTime_OffTrigger(String funcname);
void __fastcall MeasureProcTime_GetResults();

#endif
```

```UtilMeasureProcTime.cpp
//---------------------------------------------------------------------------

#include <vcl.h>
#pragma hdrstop

#include <stdint.h>

//---------------------------------------------------------------------------
#pragma package(smart_init)

/*
v0.4 2016/10/07
	- MeasureProcTime_GetResults()追加
		+ 仮実装
	- MeasureProcTime_OffTrigger()追加
	- MeasureProcTime_OnTrigger()追加

v0.3以前 2016/10/07
	- テスト実装
*/

static _LARGE_INTEGER s_Freq;
static _LARGE_INTEGER s_StartCount;
static _LARGE_INTEGER s_StopCount;
static int s_pos = -1;
#define MAX_NUM (10)
static double s_proc_msec[MAX_NUM] = {0.0};
static String s_functionNames[MAX_NUM] = { L"" };

void __fastcall MeasureProcTime_OnTrigger(String funcname)
{
	QueryPerformanceFrequency(&s_Freq);
	QueryPerformanceCounter(&s_StartCount);
}

void __fastcall MeasureProcTime_OffTrigger(String funcname)
{
	QueryPerformanceCounter(&s_StopCount);

	double timing_sec = (double)(s_StopCount.QuadPart - s_StartCount.QuadPart) / s_Freq.QuadPart;
	double timing_msec = timing_sec * 1000;
	s_pos++;
	if (s_pos >= MAX_NUM) {
		return; // overflow
	}
	s_proc_msec[s_pos] = timing_msec;
	s_functionNames[s_pos] = funcname;
}

void __fastcall MeasureProcTime_GetResults()
{
	String msg;

	for(int idx = 0; idx < MAX_NUM; idx++) {
		if (s_functionNames[idx].Length() == 0) {
			continue;
		}
		if (msg.Length() > 0) {
			msg = msg + L"\r\n";
		}
		msg = msg + String().sprintf(L"%20s : %.6f msec", s_functionNames[idx], s_proc_msec[idx]);
	}

   	OutputDebugString(msg.c_str());
	int nop=1; // breakpoint to check s_proc_msec[], s_functionNames[]
}
```

### 使用例

```Unit1.h
//---------------------------------------------------------------------------

#ifndef Unit1H
#define Unit1H
//---------------------------------------------------------------------------
#include <System.Classes.hpp>
#include <Vcl.Controls.hpp>
#include <Vcl.StdCtrls.hpp>
#include <Vcl.Forms.hpp>
//---------------------------------------------------------------------------
class TForm1 : public TForm
{
__published:	// IDE で管理されるコンポーネント
	TButton *Button1;
	void __fastcall Button1Click(TObject *Sender);
private:	// ユーザー宣言
public:		// ユーザー宣言
	__fastcall TForm1(TComponent* Owner);
};
//---------------------------------------------------------------------------
extern PACKAGE TForm1 *Form1;
//---------------------------------------------------------------------------
#endif
```

```Unit1.cpp
//---------------------------------------------------------------------------

#include <vcl.h>
#pragma hdrstop

#include <math.h>
#include "Unit1.h"

#include "UtilMeasureProcTime.h"

//---------------------------------------------------------------------------
#pragma package(smart_init)
#pragma resource "*.dfm"
TForm1 *Form1;
//---------------------------------------------------------------------------
__fastcall TForm1::TForm1(TComponent* Owner)
	: TForm(Owner)
{
}
//---------------------------------------------------------------------------

long int factorial(int m)
{
	if (m==0 || m==1) return (1);
	else      return (m*factorial(m-1));
}
double power(double x,int n)
{
	double val=1;
	int i;
	for (i=1;i<=n;i++)
	{
		val*=x;
	}
	return val;
}

double sine(double x)
{
	int n;
	double val=0;
	for (n=0;n<8;n++)
	{
MEASURE_PROC_TIME_CHECK(
		double p = power(-1,n);
		double px = power(x,2*n+1);
		long fac = factorial(2*n+1);
		val += p * px / fac;
, L"power"
)
	}
	return val;
}

//---------------------------------------------------------------------------

void __fastcall TForm1::Button1Click(TObject *Sender)
{
	double x;
	double deg2pi = acos(-1.0) / 180.0;


//MEASURE_PROC_TIME_CHECK(
	for(int loop = 0; loop < 3000; loop++) {
		x = sine(loop * deg2pi);
		int nop=1;
	}
//, L"sine"
//)

	MeasureProcTime_GetResults();

	//
}
//---------------------------------------------------------------------------
```

```txt:結果
デバッグ出力:
               power : 0.000908 msec
               power : 0.000629 msec
               power : 0.000629 msec
               power : 0.000629 msec
               power : 0.000629 msec
               power : 0.000629 msec
               power : 0.000698 msec
               power : 0.000698 msec
               power : 0.000629 msec
               power : 0.000559 msec
```

### 注意

上記の処理時間は正確な「絶対時間」ではないように思う。

複数の関数の処理時間比較（相対時間）としては使えると思われる。

(追記)
ただのC実装に`#include "UtilMeasureProctime.h"`を追加すると「String型が見つからない」というエラーが出た。
上のコード(UtilMeasureProcTime.h)に`#include <System.hpp>`を追加した。
XE4での計測時だけ`#include "UtilMeasureProctime.h"`を有効にして使う。


### 使ってみた

以下のような処理で計測してみた。

![qiita.png](https://qiita-image-store.s3.amazonaws.com/0/32870/41894fa7-2986-b5e4-24ca-1e3b081e2bd3.png)

同じ階層にある4つの関数コールの処理時間は以下となった。

```txt:結果
デバッグ出力:
                at 1 : 1.470578 msec
                at 2 : 0.000559 msec
                at 3 : 0.000559 msec
                at 4 : 0.014108 msec
                at 1 : 1.064311 msec
                at 2 : 0.000629 msec
                at 3 : 0.000559 msec
                at 4 : 0.001117 msec
```

1の処理が明らかに遅い。


### code v0.5 > OutputDebugString()を複数回実行

String msgにデバッグ情報を格納してOutputDebugString(msg.c_str())で出力していた。

そうすると、メッセージ数が多い時にString 3200文字制限にひっかかり、全部のデバッグ情報が表示されなかった。
関連 http://qiita.com/7of9/items/a5ebf4e419c1ef490a16

ある程度の長さになったらOutputDebugString()するようにした。

```UtilMeasureProcTime.cpp
//---------------------------------------------------------------------------

#include <vcl.h>
#pragma hdrstop

#include <stdint.h>

//---------------------------------------------------------------------------
#pragma package(smart_init)

/*
v0.5 2016/10/11
	- fix bug > MeasureProcTime_GetResults() > String型 3200文字制限を回避
		+ デバッグ情報が全部表示できていなかった
	- [MAX_NUM]を10から110に増やした
v0.4 2016/10/07
	- MeasureProcTime_GetResults()追加
		+ 仮実装
	- MeasureProcTime_OffTrigger()追加
	- MeasureProcTime_OnTrigger()追加

v0.3以前 2016/10/07
	- テスト実装
*/

static _LARGE_INTEGER s_Freq;
static _LARGE_INTEGER s_StartCount;
static _LARGE_INTEGER s_StopCount;
static int s_pos = -1;
#define MAX_NUM (110)
static double s_proc_msec[MAX_NUM] = {0.0};
static String s_functionNames[MAX_NUM] = { L"" };

void __fastcall MeasureProcTime_OnTrigger(String funcname)
{
	QueryPerformanceFrequency(&s_Freq);
	QueryPerformanceCounter(&s_StartCount);
}

void __fastcall MeasureProcTime_OffTrigger(String funcname)
{
	QueryPerformanceCounter(&s_StopCount);

	double timing_sec = (double)(s_StopCount.QuadPart - s_StartCount.QuadPart) / s_Freq.QuadPart;
	double timing_msec = timing_sec * 1000;
	s_pos++;
	if (s_pos >= MAX_NUM) {
		return; // overflow
	}
	s_proc_msec[s_pos] = timing_msec;
	s_functionNames[s_pos] = funcname;
}

void __fastcall MeasureProcTime_GetResults()
{
	String msg;

	for(int idx = 0; idx < MAX_NUM; idx++) {
		if (s_functionNames[idx].Length() == 0) {
			continue;
		}
		if (msg.Length() > 0) {
			msg = msg + L"\r\n";
		}
		msg = msg + String().sprintf(L"%20s : %.6f msec", s_functionNames[idx], s_proc_msec[idx]);

		if (msg.Length() > 1000) {
			OutputDebugString(msg.c_str());
			msg = L"";
		}
	}

	OutputDebugString(msg.c_str());
	int nop=1; // breakpoint to check s_proc_msec[], s_functionNames[]
}
```

### バグ?

110回のループ内の関数実行速度を測定した時、以下のような結果になった。

- ほとんど速度: 0.02msec
- 1,2個の速度: 0.8msec

上記の遅い処理の位置は、実行のたびに変化する (例: インデックス 95, 61, 75など)。

実装に不具合があるのか、キャッシュなどの関係か不明だが、あまり詳細は見れないのかもしれない。