プロファイリング(実行速度分析)

プロファイリングとは?

作成したプログラム中で使用される関数毎に、その実行回数や実行時間を分析して表示するツールがプロファイラ(gprof)であり、そのような分析をプロファイリングと呼ぶ。

プロファイリングの実際

コンパイル時に、-pg オプションをつけて、プログラムをコンパイルする。

(3F実習室のAIXマシンでは、gcc が正しくインストールされていないため、 gcc では、-pgオプションは使えない)

例

cc -o swap_sort swap_sort.c -pg

プログラムを実行すると、gmon.out というファイルができあがる。

swap_sort > /dev/null
ls gmon.out
gmon.out

gprof を起動して、プロファイリングを行なう。出力はかなり大量なので、パイプを通して、less を使って見ると良い。gprof の使用方法は、

gprof オプション 実行ファイル名 プロファイリングデータファイル(gmon.out)

である。

gprof -b swap_sort gmon.out | less

プロファイリング結果の見方

重要なのは、最後の方に表示される、

granularity: each sample hit covers 4 byte(s) Total time: 27.45 seconds

  %   cumulative   self              self     total           
 time   seconds  seconds     calls  ms/call  ms/call  name    
 45.5      12.50    12.50                             .__mcount [4]
 31.2      21.06     8.56        1  8560.00 13710.00  .swap_sort [3]
 18.8      26.21     5.15 18551089     0.00     0.00  .swap [5]
  2.0      26.76     0.55                             .__stack_pointer [6]
  1.1      27.05     0.29                             .qincrement1 [7]
  1.0      27.33     0.28                             .qincrement [8]
  0.2      27.39     0.06    20002     0.00     0.00  ._doprnt [9]
  0.1      27.43     0.04                             .__mcount [11]
  0.1      27.45     0.02                             .__itrunc [12]
  0.0      27.45     0.00    20002     0.00     0.00  .printf [10]
  0.0      27.45     0.00    10000     0.00     0.00  .rand [13]
途中省略
  0.0      27.45     0.00        1     0.00     0.00  .srand [36]
  0.0      27.45     0.00        1     0.00     0.00  .time [37]

のような部分である。先頭の行は実行に、27.45秒かかったことを示す。次の表は、左の桁から、

実行時間(全体に対する %)
実行時間の累積(秒)
実行時間(秒)
関数の実行された回数
１回の関数実行にかかる時間(ミリ秒)
１回の関数実行にかかる時間の合計(ミリ秒)
関数名

を表しており、各関数が何回実行され、どれだけ時間がかかっているかを調べることができる。自分が使った関数以外の関数も表示されていることがあるが、それらは、Cの標準関数(printfなど)から呼び出される関数である。

この結果は、同じプログラムについてでも、

最適化
コンパイラ
マシンのアーキテクチャ

が異なれば異なる可能性が高い。ちなみに、別の種類のCPU、別のコンパイラにより同じプログラムをコンパイルして、プロファイリングした結果を以下に示す。プロファイラも異なるので、表示の形式も多少異なる。

Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  ms/call  ms/call  name    
 51.80      8.07     8.07        1  8070.00  9930.00  swap_sort
 36.07     13.69     5.62                             mcount
 11.94     15.55     1.86 18463766     0.00     0.00  swap
  0.19     15.58     0.03        2    15.00    15.00  out_data
  0.00     15.58     0.00        1     0.00  9960.00  main
  0.00     15.58     0.00        1     0.00     0.00  rand_out

akira@rsch.tuis.ac.jp