2009年10月20日

perfコマンドを試してみる(3) annotateとperformance counterの実装

さて、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で偏差を含めてカウントしたり、その他今回紹介しなかった様々な機能を持ちます。皆さん是非遊んでみてください。

どうでもいいこと



今使っているブログシステムは<を入力するのに&lt;と入力しなければならず、またタグも全部手打ちと大変使いづらいです。
近いうちにはてなあたりに引っ越すかもしれません。はてな記法万歳。
posted by chun at 23:37| 日記

perfコマンドを試してみる(2) 関数ごとのオーバーヘッド

perfコマンドでおそらく一番良く使われることになるのはこれでは無いかと思います。
perf recordコマンドでコマンド実行の際のデータを収集し、

% perf record -- ./saa build chr22.txt
[ perf record: Captured and wrote 20.376 MB perf.data (~890258 samples) ]

perf reportコマンドで結果を出力します。

% perf report
# Samples: 386487
#
# Overhead Command Shared Object Symbol
# ........ ....... ......................... ......
#
56.26% saa ./saa [.] induceSA
39.16% saa ./saa [.] sais_main
0.57% saa ./saa [.] suffix_array::build_buffer(std::vector<unsigned c
0.54% saa [kernel] [k] copy_user_generic_string
0.29% saa [kernel] [k] clear_page_c
0.18% saa ./saa [.] getBuckets
0.11% saa /lib/libc-2.10.1.so [.] memset
...


この例ではSA-ISを使って遊んでいたので、saisの関数が表示されれています。どこで時間を使っているかが一目瞭然ですね。

call graph付きでプロファイルを取ることもできます。この場合、-g付きでrecordを走らせ、reportも-g付きで実行します。ただ、この場合ユーザープログラムの側のcall graphは見えません。理由はちょっと謎なので後で調べてみようと思います。

% rm perf.data
% perf record -g -- ./saa build chr22.txt
% perf report -g
55.16% saa ./saa [.] induceSA

38.59% saa ./saa [.] sais_main

0.59% saa [kernel] [k] copy_user_generic_string
|
|--85.17%-- generic_perform_write
| generic_file_buffered_write
| xfs_write [xfs]
| xfs_file_aio_write [xfs]
...


しかし、perfはただのCPU時間プロファイラではありません。perf listをするとperfで取れるパフォーマンスカウンタの一覧が分かります。cache miss, branch miss, TLB miss, page faults, kernel page allocationなども取ることができます。(回数ではなく、オーバーヘッドを計測するものと思われます。この辺はprefの実装にも関係してくるのですが、後ほど時間があれば調べて書きたいです)
% perf record -e branch-misses -- ...
% perf report


常日頃からCPUに必要なのは良いプロファイラだと言っている(嘘)私ですが、perfは素晴らしいです。このご時世にC/C++をわざわざ使っているようなプログラマはこの恩恵が分かるはずです。みなさん進んで2.6.31のヒトバシラーになりましょう!!!1121!

(次回に続く)

おまけ
前回のやり方だとmanが入らないので、追加で
sudo aptitude install asciidoc
make doc && make install-doc

しておくと良いです。
posted by chun at 06:09| 日記