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だったら全く使えない