gprofで行単位のプロファイルを出力する

gprof

環境

この記事の内容は、以下の環境で確認しました。

行単位のプロファイル

gprofは従来、関数単位で実行時間を出力します。しかし大きい関数をプロファイルしたとき、関数内のどこで時間がかかっているか知りたくなりました。そこで、行単位の実行時間を出力する簡単なパッチを書いてみました。

--- gprof/hist.c.orig   2010-07-04 00:46:05.000000000 +0900
+++ gprof/hist.c        2010-07-04 17:16:54.000000000 +0900
@@ -368,6 +368,16 @@
 
   bfd_vma lowpc = r->lowpc / sizeof (UNIT);
 
+  for (i = 0; i < r->num_bins; i++) {
+      bin_count = r->sample[i];
+      if (bin_count == 0) {
+       continue;
+      }
+      bin_low_pc = lowpc + (bfd_vma) (hist_scale * i);
+      bin_high_pc = lowpc + (bfd_vma) (hist_scale * (i + 1));
+      printf("0x%lx-0x%lx:%u\n", sizeof(UNIT) * bin_low_pc, sizeof(UNIT) * bin_high_pc, bin_count);
+  }
+
   /* Iterate over all sample bins.  */
   for (i = 0, j = 1; i < r->num_bins; ++i)
     {

上のパッチを当ててgprofをコンパイルします。すると、gprofでgmon.outを読み込んだとき、以下のような出力が得られます。

0x8080e00-0x8080e04:1
0x8080e08-0x8080e0c:1
0x8080e10-0x8080e14:2
0x8080e1c-0x8080e20:3
0x8080e24-0x8080e28:2
0x8080e28-0x8080e2c:1
0x8080e30-0x8080e34:1
..(snip)..

各行に、プログラムカウンタの開始アドレス、終了アドレス、ticks数（これが大きいほど時間がかかっている）の順に並んでいます。あとはこの情報とaddr2lineを組み合わせれば、どこで時間がかかっているか分かると思います。