プロファイラの実装

We also found that less than 4% of a program generally accounts for more than half of its running time.
　　ーー Donald Knuth, 1971

性能解析の定石としてプロファイラの使用が挙げられるが、その実装がどうなっているのか、追ってみたい。ソフトウェアに対して「プロファイル」という用語を使い始めたのは、Donald Knuthによる1971年の論文"An empirical study of FORTRAN programs," Software - Practice and Experience 1 (2) かららしい。プロファイラの仕事は関数の呼出し回数、実行時間、コールグラフを取得することであるが、GNU gprofの実装と比較すると呼出し回数の測定には同じ手法を用いているが、実行時間の測定は異なっていることがわかった。

まずは簡単な使い方から。例題はGNU ProfilerにならってCollatz予想を解くプログラム。

#include <u.h>
#include <libc.h>

unsigned int step(unsigned int x)
{
  if (x % 2 == 0)
    return x / 2;
  else
    return 3 * x + 1;
}

unsigned int nseq(unsigned int x0)
{
  unsigned int i = 1, x;

  if (x0 == 1 || x0 == 0)
    return i;

  x = step(x0);

  while (x != 1 && x != 0) {
    x = step(x);
    i++;
  }

  return i;
}

void main()
{
  unsigned int i, m = 0, im = 0;

  for (i = 1; i < 500000; i++) {
    unsigned int k = nseq(i);

    if (k > m) {
      m = k;
      im = i;
      printf("sequence length = %d for %d\n", m, im);
    }
  }
  exits(nil);
}

プロファイラを使う場合は、ローダのオプションに-pを付けて実行する。そして、プログラムを実行するとprof.というファイルが生成されるので、これをprofコマンドに食わせる。

cpu% 8c collatz.c
cpu% 8l -p -o collatz collatz.8
cpu% collatz
sequence length = 1 for 1
sequence length = 7 for 3
sequence length = 8 for 6
sequence length = 16 for 7
sequence length = 19 for 9
sequence length = 20 for 18
sequence length = 23 for 25
:
sequence length = 442 for 230631
sequence length = 448 for 410011

オプションなしで実行すると関数ごとの実行時間と呼出し回数がフラットに表示される。

cpu% prof collatz prof.209681
% Time Calls Name
51.0 22.747 499999 nseq
48.6 21.673 62135400 step
0.4 0.187 1 main
0.0 0.000 1 read
0.0 0.000 1 getpid
0.0 0.000 1 _tas
0.0 0.000 1 memset
0.0 0.000 40 write
0.0 0.000 80 _ifmt
0.0 0.000 80 _fmtcpy
0.0 0.000 80 _fmtpad
0.0 0.000 40 dofmt
0.0 0.000 1 lock
0.0 0.000 40 fmtfdinit
0.0 0.000 40 print
0.0 0.000 1 atol
0.0 0.000 1 unlock
0.0 0.000 40 vfprint
0.0 0.000 40 _fmtFdFlush
0.0 0.000 80 fmtfmt
0.0 0.000 80 _fmtdispatch
0.0 0.000 1 _fmtinstall
0.0 0.000 1 _fmtlock
0.0 0.000 1 _fmtunlock
0.0 0.000 80 chartorune

また-dオプションを付けると、コールグラフが表示される。その表示フォーマットは「シンボル:時間（ミリ秒）/呼出し回数」。

cpu% prof -d collatz prof.209615
main:44622
. nseq:44421/499999
. step:21655/62135400
. print:20/40
. vfprint:20/40
. . fmtfdinit:0/40
. . dofmt:20/40
. . _fmtdispatch:20/80
. . . chartorune:0/200
. . . fmtfmt:0/200
. . . _fmtlock:0/43
. . . . lock:0/43
. . . . _tas:0/43
. . . _fmtinstall:0/3
. . . _fmtunlock:0/43
. . . . unlock:0/43
. . . _flagfmt:0/120
. . . _efgfmt:19/40
. . . _floatfmt:18/40
. . . . xdtoa:18/40
. . . . isNaN:0/40
. . . . isInf:0/80
. . . . frexp:0/40
. . . . pow10:0/242
. . . . . pow10:0/20
. . . . sprint:0/40
. . . . . vsnprint:0/40
. . . . . dofmt:0/40
. . . . . . ...
. . . . strtod:17/40
. . . . . mulascii:4/1603
. . . . . memcmp:0/1603
. . . . . mulby:2/1603
. . . . . divby:0/40
. . . . . _divby:0/62
. . . . . memmove:0/37
. . . . . memset:0/37
. . . . . umuldiv:0/80
. . . . . frnorm:0/1227
. . . . . fpcmp:11/1200
. . . . . frnorm:5/15960
. . . . . ldexp:0/40
. . . . xadd:0/40
. . . . strlen:0/80
. . . . _fmtcpy:0/40
. . . . _fmtpad:0/40
. . . _badfmt:0/40
. . . _fmtcpy:0/40
. . . . _fmtpad:0/40
. . _fmtFdFlush:0/40
. . write:0/40
getpid:0
. memset:0
. read:0
. atol:0

では、ローダに-pオプションを与えると何が変わるのか見ていこう。nmで調べてみるとプロファイルを有効にした場合に_profXXXという関数が増えていることがわかる。

cpu% nm collatz |grep _prof
1444 T _profdump
116a T _profin
1782 T _profinit
17f7 T _profmain
1309 T _profout

_profinと_profoutが関数の出入りのフック関数と想像できる。これを確かめるためにacidでstep関数をディスアセンブラしてみる。関数の先頭にCALL _profin(SB)がRETの前にCALL _profout(SB)が追加されている。

acid: asm(step)
step 0x00001020 CALL _profin(SB)
step+0x5 0x00001025 MOVL x+0x0(FP),AX
step+0x9 0x00001029 MOVL AX,CX
step+0xb 0x0000102b ANDL $0x1,AX
step+0xe 0x0000102e CMPL AX,$0x0
step+0x11 0x00001031 JNE step+0x1d(SB)
step+0x13 0x00001033 MOVL CX,AX
step+0x15 0x00001035 SHRL AX
step+0x17 0x00001037 CALL _profout(SB)
step+0x1c 0x0000103c RET
step+0x1d 0x0000103d MOVL $0x3,AX
step+0x22 0x00001042 MULL AX,CX
step+0x24 0x00001044 INCL AX
step+0x25 0x00001045 CALL _profout(SB)
step+0x2a 0x0000104a RET

ローダのコード（/sys/src/cmd/8l/obj.c）を見てみるとTEXT疑似命令には_profinの呼出しを、RET命令には_profoutの呼出しを追加するようになっていた。また、a.outのエントリ関数も_mainではなく_mainp（/sys/src/libc/386/main9p.s）になっており、プロファイリング用データ構造の初期化などが行われるようになっている。_mainpはCのmain関数の前に_profmain関数を呼び出す。_profmainではatexit関数で_profdump関数を登録し、実行終了時にprof.ファイルを出力するようにしている。

プロファイラのコードは/sys/src/libc/port/profile.cにある。プロセスごとのプロファイリング情報を格納するためにstruct Tosが使われており、コールグラフを保持するリンクやサイクル数（kernelとkernel+user）などが記録される。サイクル数の測定はアーキテクチャ依存だが、386の場合はTSCを使っている。gprofは実行時間の測定にサンプリングを用いているのに対して、Plan9のprofの手法は確実だがオーバヘッドが大きいと言える。

（余談）gprofの実装については「プロファイラのしくみ」など。実行時間の測定はSIGPROFシグナルによるサンプリングによって行っている。