C/C++のコードの速度を改善するときに有効な方法は、処理時間を多く消費する関数を見極めて、その関数を改善することである。どの関数が(1)どれだけ処理時間を消費するか、(2)何度呼ばれているか、(3)どの関数を呼んでいる/どの関数に呼ばれているか、などを測定する行為をプロファイリングといい、その手助けをするツールをプロファイラと呼ぶ。今回はC/C++のプロファイラとして有名なgprofの使い方を紹介する。
プログラムの例
GNUプロファイラーによるコード処理速度の向上 のコードを参考にして作成した以下のコードをgprofでプロファイリングしてみよう。main()はa()とb()を100000回呼ぶ。b()はa()の約4倍時間を消費する。またmain()自身も、a()とb()を呼び出してその結果を待つ以外に、a()の約1/3の時間を消費する。
// main.cpp #include <cstdio> int a(void) { int i=0,g=0; while(i++<100000) { g+=i; } return g; } int b(void) { int i=0,g=0; while(i++<400000) { g+=i; } return g; } int main() { int iterations = 100000; while(iterations--) { a(); b(); int i=0,g=0; while(i++<30000) { g+=i; } } return 0; }
gprofを使う
gprofを使うには、まずgccで-pgオプションを使ってコンパイルする。このオプションを付けることで、プロファイリングに必要な情報がa.outに埋め込まれる。
$ g++ -pg main.cpp
次に、プログラムを実行する。その結果、デフォルトではgmon.outという名前のファイルが生成される。(gmonって何の略なんでしょうね？)
$ ./a.out
最後に、プロファイリングの結果を見るためにgprofを呼ぶ。2つ目の引数gmon.outは省略可能。
$ gprof a.out gmon.out
プロファイリング結果の見方 - Flat profile
プロファイリング結果の前半には、時間を多く消費する関数順にリストが表示される。以下は表示例である。
Flat profile: Each sample counts as 0.01 seconds. % cumulative self self total time seconds seconds calls us/call us/call name 75.37 63.28 63.28 100000 632.80 632.80 b() 18.76 79.03 15.75 100000 157.50 157.50 a() 5.87 83.96 4.93 main
一行目の"Each sample counts as 0.01 seconds."は、時間測定の分解能が0.01秒であることを示す。
各列の読み方は以下のとおりである。
これを見ると、b(), a(), main()の順に消費時間が長いことが分かる。また、b()の消費時間は63.28秒、a()の消費時間は15.75秒で、b()はa()の約4倍時間を消費していることが分かる。注意すべきは、self seconds(関数の消費時間)には、その関数がサブ関数を呼んでその結果を待っている時間は含まれないということ。例えばmain()の消費時間である4.93秒には、a()やb()を呼んでその結果を待っている時間は含まれていない。
プロファイリング結果の見方 - Call graph
プロファイリング結果の後半には、関数の呼び出し関係（コールグラフ）が表示される。以下は表示例である。
granularity: each sample hit covers 4 byte(s) for 0.01% of 83.96 seconds
index % time self children called name
<spontaneous>
[1] 100.0 4.93 79.03 main [1]
63.28 0.00 100000/100000 b() [2]
15.75 0.00 100000/100000 a() [3]
-----------------------------------------------
63.28 0.00 100000/100000 main [1]
[2] 75.4 63.28 0.00 100000 b() [2]
-----------------------------------------------
15.75 0.00 100000/100000 main [1]
[3] 18.8 15.75 0.00 100000 a() [3]
-----------------------------------------------granularityの意味は正直よくわからない。½¾Íè¤Î¥×¥í¥Õ¥¡¥¤¥ë¥Ä¡¼¥ëに一応日本語の説明があるのだが…。
その下には、関数の呼び出し関係が、関数ごとに表示される。1つ目のブロックは、main()の呼び出し関係を分析している。これによると、main()はa()とb()を呼び出していることがわかる。
b()の左にある100000/100000というのは、b()が呼び出された回数(分母の100000)のうち、main()がb()を呼び出した回数(分子の100000)という意味である。
[1], [2], [3]などの数字は、各関数に付けられたIDである。
2つ目のブロック、3つ目のブロックも同様にb(), a()の呼び出し関係を分析している。
プログラム全体の処理時間が短い時のTips
プログラム全体の処理時間がgprofの分解能(今回の場合では0.01秒)に比べてあまり大きくない時は、プログラムを違うデータで何回が実行し、出力された複数のgmon.outを結合する技が使える。結合にはgprofの-sオプションを使う。詳しくはGNU gprofの"Statistical Inaccuracy of gprof Output"を参照。
ソースコード中に実行回数を表示するTips
gccのオプションにさらに-gを加え、gprofのオプションにさらに-Aを加えると、ソースコードのどの行が何回実行されたかが分かる。
$ g++ -g -pg main.cpp $ ./a.out $ gprof a.out -A
出力例は以下の通り。
*** File /home/minus9d/gprof/main.cpp:
// main.cpp
#include <cstdio>
100000 -> int a(void) {
int i=0,g=0;
while(i++<100000)
{
g+=i;
}
return g;
}
100000 -> int b(void) {
int i=0,g=0;
while(i++<400000)
{
g+=i;
}
return g;
}
##### -> int main()
{
int iterations = 100000;
while(iterations--)
{
a();
b();
int i=0,g=0;
while(i++<30000)
{
g+=i;
}
}
return 0;
}
Top 10 Lines:
Line Count
5 100000
13 100000
Execution Summary:
3 Executable lines in this file
3 Lines executed
100.00 Percent of the file executed
200000 Total number of line executions
66666.67 Average executions per line
類似のツール
- gperftools - Fast, multi-threaded malloc() and nifty performance analysis tools - Google Project Hosting
- googleが開発するツール。gprofよりも多くのことができるっぽい
- OProfile - A System Profiler for Linux (News)
- より高い分解能で測定できるっぽい
- Command-Line Profiling Tools Reference
- Visual Studio用のプロファイラ