Objective-Cのボトルネック検出

パフォーマンスの改善には、ボトルネックの検出が欠かせません。
どの処理に時間がかかっているのか判別するため、処理の経過時間を記録します。

stackoverflow*1では以下のような方法が提案されています。

NSDate *start = [NSDate date];
// do stuff...
NSTimeInterval timeInterval = [start timeIntervalSinceNow];

これで経過時間を取得できます。
が、しかし。「１回だけ経過時間を取得する」なんてことは、あまりありません。
たとえば、「あるメソッド内で行われている処理の中で、一番重い処理を見つけたい」といったときには、メソッドの処理を５個くらいに分割してそれぞれの経過時間を取得し、大雑把なアタリをつける方が効率的です。
つまり、経過時間を取得する処理が複数回おこなわれます。
しかし、経過時間を取得するたびにログを吐いていると、NSLog自体がかなり重い処理のため、計測結果が大きく狂います。これを避けるためには、経過時間を配列で保持しておいて、すべて取得してからまとめてログを吐いてやる必要があります。

意外と面倒くさいです。

面倒くさいコードを何度も書きたくないので、マクロ化しました。

#define PTStart \
int PTIndex = 0;\
double PTElapledTimes[100] = {0.0f};\
int PTLines[100] = {0};\
char PTComments[100][30] = {'\n'};\
int PTStartLine = __LINE__;\
CFAbsoluteTime PTStartTime = CFAbsoluteTimeGetCurrent();\
CFAbsoluteTime PTCurrent = CFAbsoluteTimeGetCurrent();

#define PTGetDuration(comment) \
PTLines[PTIndex] = __LINE__;\
strcpy(PTComments[PTIndex], comment);\
PTElapledTimes[PTIndex++] = CFAbsoluteTimeGetCurrent() - PTCurrent;\
PTCurrent = CFAbsoluteTimeGetCurrent();

#define PTPrintResult  \
NSLog(@"%s", __PRETTY_FUNCTION__);\
NSLog(@"total duration: %f", CFAbsoluteTimeGetCurrent() - PTStartTime);\
for (int i = 0; i < PTIndex; i++) {\
int sl = i == 0 ? PTStartLine : PTLines[i-1];\
NSLog(@"%04d-%04d\telapsed:%.10f\t%s", sl, PTLines[i], PTElapledTimes[i], PTComments[i]);\
}

関数ではなくマクロなので、計測対象コードの中にインライン展開されることとなり、名前空間が分かれません。そのため、一応変数にPrefixをつけています。
PTStartで取得開始、経過時間を取得したい行にPTGetDuration(comment)、最後にPTPrintResultで出力します。
出力内容は以下の通り、ラインナンバー・経過時間・コメントとなっています。

PTStart

takz(1, 0, 0);

PTGetDuration("1,0,0")

takz(10, 0, 0);

PTGetDuration("10,0,0")

takz(12, 6, 0);

PTGetDuration("12,6,0")

takz(18, 9, 0);

PTGetDuration("18,9,0")

PTPrintResult

/* 出力 */
PerformanceTimer[5692:303] int main(int, const char **)
PerformanceTimer[5692:303] total duration: 0.053143
PerformanceTimer[5692:303] 0022-0026	elapsed:0.0000050068	1,0,0
PerformanceTimer[5692:303] 0026-0030	elapsed:0.0000000000	10,0,0
PerformanceTimer[5692:303] 0030-0034	elapsed:0.0002049804	12,6,0
PerformanceTimer[5692:303] 0034-0038	elapsed:0.0512049794	18,9,0

Github:
https://github.com/oropon/PerformanceTimer

*1:http://stackoverflow.com/questions/741830/getting-the-time-elapsed-objective-c