gprofを使いこなす


このエントリーをはてなブックマークに追加

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

類似のツール