OProfileの使い方備忘録
プログラムのボトルネックがどこにあるのか、なんて調べるときには計測する必要がありますね。プログラム中の特定処理の前後でrdtsc命令使って時間を計測して処理時間を求める、とかそういうこともできるんですけど、まあめんどうじゃないですか。プロファイラを使いましょう。
プロファイラとはなんぞや、Wikipediaの性能解析のページに色々書いてますね。
そういうわけでOProfileというLinuxで動くプロファイラを使っているので、未来の自分とか「OProfile動かしてみてーけどさっぱりわからん！」みたいな人のためにまとめておきます。
OProfileの特徴
OProfileは
- 計測したいプログラムに対して特別な処理をしなくてもいい
- 低レイヤーの情報も計測できる
- gprof形式のコールグラフも表示できる
- オーバーヘッドがとても小さい
これらの特徴があるらしいです。使ってみて特に嬉しいと感じたのは「低レイヤーの情報も計測できる」ですね。CPUの種類にもよる*1のですが処理時間だけではなく、L1キャッシュミスした回数やらDRAMアクセス回数とかがプログラムのどこで発生しているのか一目でわかったりするのは、いやなんともすごいものだなあと感嘆の念を覚えます。
インストール
まず対応しているCPUはだいたい
http://oprofile.sourceforge.net/docs/
の最後の「Event type reference」にまとめられてると思いますが、ソースコード見た感じ、ここに書かれていないものもちょっとは対応とかされてる気もします。無かったら書けばいいんじゃないですか！
今回入れる環境のCPUは
$ cat /proc/cpuinfo processor : 0 vendor_id : AuthenticAMD cpu family : 15 model : 43 model name : AMD Athlon(tm)64 X2 Dual Core Processor 4600+ ...
AMD Athlon64ということで幸いにも対応しているのでOProfileをインストールすることにします。OSはUbuntu 8.10。この環境だとこんな硬派なOProfileですら
$ sudo apt-get install oprofile oprofile-gui
こんなに軟派に一行でインストールできる。
# カーネルプログラムのプロファイルまで取りたいならカーネル再構築してvmlinux作らないといけないので、それなりに面倒なことをする必要がある。
使い方
oprofileは基本的にopcontrolコマンドからopcontrol --startのようにoprofileデーモンに命令を与える扱い方をします。とりあえず以下のコマンドがわかればプロファイリングっぽいことができます。
- --start-daemon
- oprofileデーモンを開始（プロファイルは始まらない）
- --start
- （デーモンが起動していなければ起動してから）プロファイルをはじめる。
- --dump
- 現在までのプロファイル結果を出力する
- --stop
- プロファイルを停止し、結果を出力する
- --shutdown
- oprofileデーモンを停止
- --reset
- プロファイル結果をリセットする
手元のバージョンのopcontrolだとルート権限が必要。ルート権限無しでも使えるバージョン（設定？）もあるようだけどそれはよくわからない。
とりあえず動かしてみたいなら、まず
$ sudo opcontrol --no-vmlinux
のように「カーネルのプロファイルまでは取らない」と設定。（設定内容は/etc/oprofile/daemonrcに保存されます）opcontrol --startでプロファイリングを開始し、opcontrol --stopで終了し、その間に動いたプログラムについて記録します。
ためしにこんなプログラムのプロファイルを取ってみます。
#include <stdio.h> #include <stdlib.h> #define ROWS 1000 #define COLS 1000 #define table_ref(table,row,col) ((table)[(row)*COLS+(col)]) typedef int* Table; void touch_row_col(Table from, Table to) { int i, j; for(i=0;i<ROWS;++i) { for(j=0;j<COLS;++j) { table_ref(from, i, j) = table_ref(to, i, j); } } } void touch_col_row(Table from, Table to) { int i, j; for(i=0;i<COLS;++i) { for(j=0;j<ROWS;++j) { table_ref(from, j, i) = table_ref(to, j, i); } } } int main() { Table from, to; from = malloc(sizeof(int)*ROWS*COLS); to = malloc(sizeof(int)*ROWS*COLS); touch_row_col(from, to); touch_col_row(from, to); return 0; }
gcc -gでコンパイルして（-gオプションを付けると、あとでopannotateでソースと並べて結果を見ることができる）、--startと--stopの間でプログラムを実行します。
$ gcc -g array.c $ sudo opcontrol --reset $ sudo opcontrol --start && ./a.out ; sudo opcontrol --stop Using default event: CPU_CLK_UNHALTED:100000:0:1:1 Using 2.6+ OProfile kernel interface. Using log file /var/lib/oprofile/samples/oprofiled.log Daemon started. Profiler running. Stopping profiling.
opreportまたはopannotateなどでプロファイルの結果を見ます。
$ opreport
CPU: AMD64 processors, speed 1000 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No u
nit mask) count 100000
CPU_CLK_UNHALT...|
samples| %|
------------------
2711 42.3461 no-vmlinux
2618 40.8935 a.out
351 5.4827 ld-2.8.90.so
343 5.3577 libc-2.8.90.so
139 2.1712 dash
53 0.8279 libglib-2.0.so.0.1800.2
25 0.3905 oprofiled
...引数を指定しないと、プロファイル中に実行されていたすべてのプロセスについて情報を表示します。特定のプログラムのプロファイル情報のみ見たい場合は引数で指定。
$ opreport a.out /usr/local/bin/zsh /bin/grep
CPU: AMD64 processors, speed 1000 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 100000
CPU_CLK_UNHALT...|
samples| %|
------------------
2618 99.3548 a.out
15 0.5693 grep
2 0.0759 zsh引数-lでシンボル情報、-cでコールグラフとあわせて表示されます。touch_col_rowがtouch_row_colに比べてとても遅いのが見て取れます。
$ opreport -l a.out CPU: AMD64 processors, speed 1000 MHz (estimated) Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 100000 samples % symbol name 2025 77.3491 touch_col_row 593 22.6509 touch_row_col $ opreport -c a.out CPU: AMD64 processors, speed 1000 MHz (estimated) Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 100000 samples % symbol name ------------------------------------------------------------------------------- 2025 77.3491 touch_col_row 2025 100.000 touch_col_row [self] ------------------------------------------------------------------------------- 593 22.6509 touch_row_col 593 100.000 touch_row_col [self] -------------------------------------------------------------------------------
opannotateでは-sでソースコード、-aでアセンブリコードとあわせた結果を表示することが可能です。
$ opannotate -s a.out
/*
* Command line: opannotate -s a.out
*
* Interpretation of command line:
* Output annotated source file with samples
* Output all files
*
* CPU: AMD64 processors, speed 1000 MHz (estimated)
* Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 100000
*/
/*
* Total samples for file : "/home/komuro/lang/c/etc/array.c"
*
* 2618 100.000
*/
:#include <stdio.h>
:#include <stdlib.h>
:#define ROWS 1000
:#define COLS 1000
:#define table_ref(table,row,col) ((table)[(row)*COLS+(col)])
:typedef int* Table;
:void touch_row_col(Table from, Table to) { /* touch_row_col total: 593 22.6509 */
: int i, j;
3 0.1146 : for(i=0;i<ROWS;++i) {
235 8.9763 : for(j=0;j<COLS;++j) {
355 13.5600 : table_ref(from, i, j) = table_ref(to, i, j);
: }
: }
:}
:void touch_col_row(Table from, Table to) { /* touch_col_row total: 2025 77.3491 */
: int i, j;
7 0.2674 : for(i=0;i<ROWS;++i) {
471 17.9908 : for(j=0;j<COLS;++j) {
1547 59.0909 : table_ref(from, j, i) = table_ref(to, j, i);
: }
: }
:}
:int main() {
: Table from, to;
: from = malloc(sizeof(int)*ROWS*COLS);
: to = malloc(sizeof(int)*ROWS*COLS);
: touch_row_col(from, to);
: touch_col_row(from, to);
: return 0;
:}
$ opannotate -a a.out
/*
* Command line: opannotate -a a.out
*
* Interpretation of command line:
* Output annotated assembly listing with samples
*
* CPU: AMD64 processors, speed 1000 MHz (estimated)
* Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (N
o unit mask) count 100000
*/
:
:/home/komuro/lang/c/etc/a.out: file format elf32-i386
:
:
:Disassembly of section .text:
:
08048422 <touch_col_row>: /* touch_col_row total: 2025 77.3491 */
: 8048422: push %ebp
: 8048423: mov %esp,%ebp
: 8048425: sub $0x10,%esp
: 8048428: movl $0x0,-0x4(%ebp)
: 804842f: jmp 8048475 <touch_col_row+0x53>
: 8048431: movl $0x0,-0x8(%ebp)
: 8048438: jmp 8048468 <touch_col_row+0x46>
80 3.0558 : 804843a: mov -0x8(%ebp),%eax
465 17.7617 : 804843d: imul $0x3e8,%eax,%eax
116 4.4309 : 8048443: add -0x4(%ebp),%eax
: 8048446: shl $0x2,%eax
: 8048449: mov %eax,%edx
454 17.3415 : 804844b: add 0x8(%ebp),%edx
: 804844e: mov -0x8(%ebp),%eax
: 8048451: imul $0x3e8,%eax,%eax
239 9.1291 : 8048457: add -0x4(%ebp),%eax
: 804845a: shl $0x2,%eax
: 804845d: add 0xc(%ebp),%eax
193 7.3720 : 8048460: mov (%eax),%eax
: 8048462: mov %eax,(%edx)
: 8048464: addl $0x1,-0x8(%ebp)
471 17.9908 : 8048468: cmpl $0x3e7,-0x8(%ebp)
: 804846f: jle 804843a <touch_col_row+0x18>
: 8048471: addl $0x1,-0x4(%ebp)
7 0.2674 : 8048475: cmpl $0x3e7,-0x4(%ebp)
: 804847c: jle 8048431 <touch_col_row+0xf>
: 804847e: leave
: 804847f: ret
...
$ opannotate -sa a.out
/*
* Command line: opannotate -sa a.out
*
* Interpretation of command line:
* Output annotated assembly listing with samples
*
* CPU: AMD64 processors, speed 1000 MHz (estimated)
* Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (N
o unit mask) count 100000
*/
:
:/home/komuro/lang/c/etc/a.out: file format elf32-i386
:
:
:Disassembly of section .text:
:
08048422 <touch_col_row>: /* touch_col_row total: 2025 77.3491 */
: for(j=0;j<COLS;++j) {
: table_ref(from, i, j) = table_ref(to, i, j);
: }
: }
:}
:void touch_col_row(Table from, Table to) {
: 8048422: push %ebp
: 8048423: mov %esp,%ebp
: 8048425: sub $0x10,%esp
: int i, j;
: for(i=0;i<ROWS;++i) {
: 8048428: movl $0x0,-0x4(%ebp)
: 804842f: jmp 8048475 <touch_col_row+0x53>
: for(j=0;j<COLS;++j) {
: 8048431: movl $0x0,-0x8(%ebp)
: 8048438: jmp 8048468 <touch_col_row+0x46>
: table_ref(from, j, i) = table_ref(to, j, i);
80 3.0558 : 804843a: mov -0x8(%ebp),%eax
465 17.7617 : 804843d: imul $0x3e8,%eax,%eax
116 4.4309 : 8048443: add -0x4(%ebp),%eax
: 8048446: shl $0x2,%eax
: 8048449: mov %eax,%edx
454 17.3415 : 804844b: add 0x8(%ebp),%edx
: 804844e: mov -0x8(%ebp),%eax
: 8048451: imul $0x3e8,%eax,%eax
239 9.1291 : 8048457: add -0x4(%ebp),%eax
: 804845a: shl $0x2,%eax
: 804845d: add 0xc(%ebp),%eax
193 7.3720 : 8048460: mov (%eax),%eax
: 8048462: mov %eax,(%edx)
: }
:}
...opcontrol --event=で補足するイベントを指定することができます。イベントの種類はドキュメントかophelpコマンドやopcontrol --list-eventsなどで表示されるものが使用可能です。
touch_col_rowがとても遅いのは、きっとメモリ領域に対するアクセスパターンが飛び飛びになってしまっててキャッシュミスが発生しまくってるんだろうなあとあたりをつけて、キャッシュミスの発生具合を見ることにしましょう。AMD64だとDATA_CACHE_MISSESとかですね。
$ sudo opcontrol --shutdown Stopping profiling. Killing daemon. $ sudo opcontrol --reset $ sudo opcontrol --event=DATA_CACHE_MISSES:500 $ sudo opcontrol --start && ./a.out ; sudo opcontrol --stop Using 2.6+ OProfile kernel interface. Using log file /var/lib/oprofile/samples/oprofiled.log Daemon started. Profiler running. Stopping profiling. $ opreport -l a.out CPU: AMD64 processors, speed 1000 MHz (estimated) Counted DATA_CACHE_MISSES events (Data cache misses) with a unit mask of 0x00 (No unit mask) count 500 samples % symbol namet 3965 95.0839 touch_col_row 205 4.9161 touch_row_col
touch_col_rowでキャッシュミスが多発していることがわかりますね。
このように、噂には聞いていて意識して書くことで実際にプログラムが速くなったりすることは確認したのだけれども、どうにも存在が遠くてよくわからないキャッシュさんを身近に感じることのできて嬉しい！ それがOProfileのしてくれた大きな仕事なのでした。ありがたいありがたい。
あとGUIから操作することとかも可能らしいんだけど全く試してないのでわからない。
*1:OProfileが対応していないCPUだったら全く使えない
