さて、perfコマンドの能力はこれだけではありません。perf annotateによって、プログラムの中のどの行が時間を食っているかが一目で分かるようになります。
% perf annotate
------------------------------------------------
Percent | Source code & Disassembly of saa
------------------------------------------------
:
:
:
: Disassembly of section .text:
:
: 0000000000407710 <sais_main>:
:
: /* find the suffix array SA of T[0..n-1] in {0..k-1}^n
: use a working space (excluding T and SA) of at most 2n+O(1) for a constant alphabet */
: static
: int
: sais_main(const unsigned char *T, int *SA, int fs, int n, int k, int cs, int isbwt) {
0.00 : 407710: 41 57 push %r15
0.00 : 407712: 41 56 push %r14
0.00 : 407714: 41 89 ce mov %ecx,%r14d
0.00 : 407717: 41 55 push %r13
...
: for(j = p + 1; (j < n) && (c0 == (c1 = chr(j))); ++j) { }
0.23 : 407942: 41 8d 40 01 lea 0x1(%r8),%eax
5.08 : 407946: 41 39 c6 cmp %eax,%r14d
0.07 : 407949: 7e 3b jle 407986
:
...
: for(i = 0, m = 0; i < n; ++i) {
8.29 : 4079a4: 4c 39 cf cmp %r9,%rdi
0.04 : 4079a7: 0f 85 73 ff ff ff jne 407920
0.00 : 4079ad: 44 89 54 24 18 mov %r10d,0x18(%rsp)
...
ちなみに、対応するコンソールを使えば色つきで表示されます。(例えば5.08%は赤色で、他の割合は青色で表示され、どこが最も重いのか一目瞭然です。)行単位でボトルネックを探すにはperf annotate -lが便利です。
Sorted summary for file /home/shun/work/saa/saa
----------------------------------------------
8.29 /home/shun/work/saa/sais/sais.c:198
7.23 /home/shun/work/saa/sais/sais.c:261
7.08 /home/shun/work/saa/sais/sais.c:261
6.52 /home/shun/work/saa/sais/sais.c:259
5.38 /home/shun/work/saa/sais/sais.c:242
5.08 /home/shun/work/saa/sais/sais.c:201
2.72 /home/shun/work/saa/sais/sais.c:180
2.70 /home/shun/work/saa/sais/sais.c:180
...
ボトルネックが一目瞭然です。198行目を書き換えればちょっと速くなるかなーなどと分かるわけです。これで速度が増えるよ やったねタエちゃん！
注意点とperfの実装
さて、よくよく見てみますと8.29%の処理時間を取っているのはレジスタ間cmp命令です。レジスタ同士の比較でなんでこんなに時間を取っているんでしょう？ それを説明するためにはperfの実装を知る必要があります。
perfはハードウェアの持つパフォーマンスカウンタを利用します。パフォーマンスカウンタはある一定のイベントが起きるごとに加算され、指定された回数のイベントが起きるごとに割り込みを掛けます。perf recordでは、この割り込みを掛けたときのIPレジスタの値を保存することができます(perfシステムコールにPERF_SAMPLE_IPを指定)。perf reportではこの値を読み出し、対応するアドレスを逆算して行番号などに割り付けます。
さて、我々が現在使っているCPUは、大抵が
アウトオブオーダー実行です。CPU内で発行されるμOPsは命令の字面とは異なる長さ、規模、順序で発行されます。そのため、実際の割り込みが起きた時点でのIPカウンタは必ずしも実際のCPU命令の実行箇所を意味しません。IPカウンタの値なんて飾りです。偉い人にはそれがわからんのです。ですので、この処理時間は「このへんにボトルネック」という意味でしかないことを理解してプロファイルを取ると良いと思います。Atom CPUならまた話が変わるかもね！
このほかperfはpidを指定してattachしたり、perf statで偏差を含めてカウントしたり、その他今回紹介しなかった様々な機能を持ちます。皆さん是非遊んでみてください。
どうでもいいこと
今使っているブログシステムは<を入力するのに<と入力しなければならず、またタグも全部手打ちと大変使いづらいです。
近いうちにはてなあたりに引っ越すかもしれません。はてな記法万歳。
