こんにちは。@kokukumaです。

これは、KLab Advent Calendar6日目の記事です。6番手も緊張しますね(棒読み)。

今日はLinuxでプログラムの挙動を追って行く時に、便利なコマンド達を紹介したいと思います。

コードを追っていく流れに合わせて、6つのパートに分けて紹介していきます。

環境はdebian前提で話しています、あしからず。

ユーザ空間で計測する

コードを追おうと思う人の目的は、「そのコードを速くしたい」がほとんどでしょう。

そんなとき、いきなりコード読んでも心が折れるだけなので、この辺のツールを使ってどこが遅いのか調べます。

time

誰でも知ってるtimeコマンド。とりあえず時間測って比較すると言ったらこれでしょうか。

real、user、sysの違いは、以下のとおり。

ネットワークやIOの待ち時間は、sysには入らず、realのみに入ります。

vagrant@debian-jessie:/krepos$ time find . >/dev/null

real    0m6.989s : 実際にかかった時間
user    0m0.028s : 実行したプログラムがCPUを使った時間
sys     0m0.464s : 実行したプログラムに伴いOSが使った時間

perf

perfはLinuxのパフォーマンス解析ツールです。

call graphを出力させることもでき、コードの把握にも役立ちます。

何も考えずインストールしてさくっと動くのが嬉しい。

vagrant@debian-jessie:~$ perf record -g ls                      <- 計測
vagrant@debian-jessie:~$ ls -l
    total 104
    -rw------- 1 vagrant vagrant 10152 Dec  1 15:03 perf.data   <- これができる.
vagrant@debian-jessie:~$ perf report -g -G                      <- 表示

gprof

gprofはいわゆるプロファイラです。

これを使えば、プログラム中のどこが遅いかを把握することができます。

ただし、これを使うためには、-pgオプションをつけてコンパイルする必要があり、若干手間です。

またperfと同様に、call graphも出力されているので、コードの把握にも役立ちます。

ただし、あくまでユーザ空間でのプロファイルなので、時間がかかっているシステムコールを見つけるとかはできません。

vagrant@debian-jessie:~$ /home/vagrant/src/tmp/sed-4.2.2/sed/sed -e "s/karin/karino/g" karino
vagrant@debian-jessie:~$ ls -l
    total 104
    -rw-r--r-- 1 vagrant vagrant 21140 Dec  1 17:06 gmon.out                           <- これができる
    -rw-r--r-- 1 vagrant vagrant     7 Nov 15 13:08 karino

vagrant@debian-jessie:~$ gprof /home/vagrant/src/tmp/sed-4.2.2/sed/sed gmon.out        <- 結果表示

    Flat profile:

    Each sample counts as 0.01 seconds.
     no time accumulated

      %   cumulative   self              self     total
     time   seconds   seconds    calls  Ts/call  Ts/call  name
      0.00      0.00     0.00       18     0.00     0.00  inchar
      0.00      0.00     0.00       15     0.00     0.00  brlen
      0.00      0.00     0.00       14     0.00     0.00  ck_malloc
      0.00      0.00     0.00       11     0.00     0.00  add1_buffer
      0.00      0.00     0.00        4     0.00     0.00  line_init
      0.00      0.00     0.00        3     0.00     0.00  ck_fflush
      0.00      0.00     0.00        3     0.00     0.00  closedown
      0.00      0.00     0.00        3     0.00     0.00  size_buffer
      0.00      0.00     0.00        3     0.00     0.00  str_append
      0.00      0.00     0.00        2     0.00     0.00  ck_fwrite
      0.00      0.00     0.00        2     0.00     0.00  ck_getdelim
      0.00      0.00     0.00        2     0.00     0.00  do_ck_fclose
      0.00      0.00     0.00        2     0.00     0.00  free_buffer
...

strace

システムコールを見たいときは、straceをつかいます。

straceは、プロセスが呼び出したシステムコールをトレースするためのコマンドです。

-cオプションをつけると、各システムコールの呼びだされた回数やかかった時間などの統計情報を出力してくれます。

これによって、どのシステムコールが遅いのかを簡単に知ることができます。

-fオプションをつけると、プログラム内部で立てられた別のスレッドから呼び出されたシステムコールもまとめて集計してくれます。

何も考えずインストールしてさくっと動くのが嬉しい。

vagrant@debian-jessie:/krepos$ strace -cf find . >/dev/null
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 55.62    0.027649          18      1496           openat
 39.53    0.019652          13      1508         6 open
  3.93    0.001955           1      1496           newfstatat
  0.91    0.000450           0      3051           getdents
  0.01    0.000006           0      2999           close
  0.00    0.000000           0         4           read
  0.00    0.000000           0       997           write
  0.00    0.000000           0      1501           fstat
  0.00    0.000000           0        13           mmap
  0.00    0.000000           0         6           mprotect
  0.00    0.000000           0         3           munmap
  0.00    0.000000           0       130           brk
  0.00    0.000000           0         3         2 ioctl
  0.00    0.000000           0         4         4 access
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           uname
  0.00    0.000000           0      2995           fchdir
  0.00    0.000000           0         1           arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00    0.049712                 16209        12 total

ユーザ空間で動くコードを読む

だいたいどの辺が遅いかがわかったら、実際にコードが読みたくなります。

apt

何はともあれ、コードを取得しなければ話は始まりません。

そんな時、地味に便利なのがaptコマンド。以下のように、aptでインストールできるものは、そのコードも簡単に取得できます。

例えば、sedのコードを読みたいと思ったら。

vagrant@debian-jessie:~/src/tmp$ apt-get source sed
    Reading package lists... Done
    Building dependency tree
    Reading state information... Done
    NOTICE: 'sed' packaging is maintained in the 'Git' version control system at:
    git://git.debian.org/users/clint/sed.git
    Need to get 1,119 kB of source archives.
    Get:1 http://httpredir.debian.org/debian/ jessie/main sed 4.2.2-4 (dsc) [1,825 B]
    Get:2 http://httpredir.debian.org/debian/ jessie/main sed 4.2.2-4 (tar) [1,059 kB]
    Get:3 http://httpredir.debian.org/debian/ jessie/main sed 4.2.2-4 (diff) [57.6 kB]
    Fetched 1,119 kB in 1s (1,046 kB/s)
    gpgv: keyblock resource `/home/vagrant/.gnupg/trustedkeys.gpg': file open error
    gpgv: Signature made Mon 10 Feb 2014 02:44:46 AM JST using RSA key ID 199D38A8
    gpgv: Can't check signature: public key not found
    dpkg-source: warning: failed to verify signature on ./sed_4.2.2-4.dsc
    dpkg-source: info: extracting sed in sed-4.2.2
    dpkg-source: info: unpacking sed_4.2.2.orig.tar.bz2
    dpkg-source: info: unpacking sed_4.2.2-4.debian.tar.xz
    dpkg-source: info: applying debian-changes

vagrant@debian-jessie:~/src/tmp$ ls -l
    total 1104
    drwxr-xr-x 11 vagrant vagrant    4096 Dec  1 13:43 sed-4.2.2
    -rw-r--r--  1 vagrant vagrant   57644 Dec  1 13:43 sed_4.2.2-4.debian.tar.xz
    -rw-r--r--  1 vagrant vagrant    1825 Dec  1 13:43 sed_4.2.2-4.dsc
    -rw-r--r--  1 vagrant vagrant 1059414 Dec  1 13:43 sed_4.2.2.orig.tar.bz2

とってきたコードをコンパイルしたいときは、作成されたディレクトリ内にあるスクリプトを使って以下のようにビルドすることができます。

また、debian/rulesの中にコンパイルオプションも記述されているので、用途にあわせて-gとかつければいいと思います。

vagrant@debian-jessie:~/src/tmp/sed-4.2.2$ debian/rules build

ctags

コードを読む際、関数の宣言元にジャンプできるようにしておかないと、読んでいくのは苦行すぎます。

一番さっと使えるのは、ctagsなのかな?。

まぁ、IDE使ってればできるだろうし、ctagsの他にもgtagsとかいろいろある。

grep

Linuxカーネルみたいに、でっかいコードを読んでると、なんだかんだで文字列を検索したくなるでしょう。

そんなときに使うのがgrep。

デフォで入ってる奴でもいいですが、ackとかagとかhighwayとか、速いgrepがいろいろあるので、そっちを使った方が良いでしょうね。

vagrant@debian-jessie:~/$ ag --nogroup (検索したい文字列)

ユーザ空間におけるコードの挙動を把握する

コードを読んでいると、だいたい心が折れます。

そもそも、コード読むだけでその挙動をすべて把握しようなんてのは無理な話です。

そんな時は、この辺のツールを使ってコードの挙動を把握します。

gdb

そこでまず登場するのが、言わずと知れたgdb。

プログラム実行中に任意の場所で止め、値を見たり、書き換えたり、いわゆる「デバッグ」ができます。

またこれを実行するには、実行ファイル中にデバッグ情報が必要になるので、プログラムをコンパイルする際、-gをつける必要があります。

よく使うgdbのコマンドはこの辺。

vagrant@debian-jessie:~/src/tmp/sed-4.2.2$ gdb sed/sed
GNU gdb (Debian 7.7.1+dfsg-5) 7.7.1
....
(gdb) directory (path)                        : 該当するソース・ファイルを検索するディレクトリを指定する。実行ファイルと同じディレクトリにあるなら指定する必要はない。
(gdb) break (関数名/行番号/フィアル名:行番号) : ブレークポイントを設定する。
(gdb) run                                     : 実行ファイル(ここでは、sed/sed)を実行する。
(gdb) list                                    : 現在止まっている周辺のコードを表示する。表示できなければ、directoryで読み込むコードのパスを指定する。
(gdb) step                                    : コードを次に進める。関数内に入る。
(gdb) next                                    : コードを次に進める。関数内には入らない。
(gdb) print (変数名/*ポインタ変数/&アドレス)  : 値を表示する。
(gdb) continue                                : 実行継続する。
(gdb) quit                                    : gdbを抜ける。

perf / gprof

gdbを使えば、読んでる部分のコードをピンポイントで把握することができます。

しかし、ピンポイント過ぎてわからないよというときもあります。

そんな時に使うのが、perf / gprofで出すcall graph。

使い方は、計測で書いたのと同じようなかんじ。

strace

計測で使ったstraceももちろん、システムコールの呼び出し状況を確認できるすごく便利なツールです。

ただし、呼び出しているシステムコールを順番に全部出力しているので、結果は非常に長くなりがち。

この中から自分が今読んでるコードの場所に対応するシステムコールを見つけるのはなかなか大変なので、比較的簡単なプログラムでしかやらないかも。

vagrant@debian-jessie:~$ strace -f find . >/dev/null
    execve("/usr/bin/find", ["find", "."], [/* 17 vars */]) = 0
    brk(0)                                  = 0x8f5000
    access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
    mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff139d28000
    access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
    open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
    fstat(3, {st_mode=S_IFREG|0644, st_size=37443, ...}) = 0
    mmap(NULL, 37443, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7ff139d1e000
    close(3)                                = 0
    access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
    open("/lib/x86_64-linux-gnu/libm.so.6", O_RDONLY|O_CLOEXEC) = 3
    read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\200U\0\0\0\0\0\0"..., 832) = 832
    fstat(3, {st_mode=S_IFREG|0644, st_size=1051056, ...}) = 0
    mmap(NULL, 3146072, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ff139809000
    mprotect(0x7ff139909000, 2093056, PROT_NONE) = 0
    mmap(0x7ff139b08000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xff000) = 0x7ff139b08000
    close(3)                                = 0
    access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
    open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
    read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\34\2\0\0\0\0\0"..., 832) = 832
    fstat(3, {st_mode=S_IFREG|0755, st_size=1729984, ...}) = 0
    mmap(NULL, 3836448, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ff139460000
    mprotect(0x7ff1395ff000, 2097152, PROT_NONE) = 0
    mmap(0x7ff1397ff000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x19f000) = 0x7ff1397ff000
    mmap(0x7ff139805000, 14880, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7ff139805000
....

カーネル空間で計測する

上記までで抱えている問題を解決できればよいですが、遅い問題がカーネル空間にあった場合、更に深く追う必要がでてきます。

ツールを使って、遅い部分を把握します。

systemtap

straceを使えば、どのシステムコールに時間がかかっているのかを把握することができます。

しかし、そのシステムコールがなぜ遅いのかを知るには不十分です。

そんな時は、実行中のLinuxカーネルの挙動をモニタリングするためのツールである systemtapが使えます。

systemtapは、プローブとプローブ起動時に実行されるコードをsystemtapスクリプトに記述しておき、計測したいプログラム実行時にそのsystemtapスクリプトを指定することで、カーネル空間のさまざまな情報を取得することができます。

プローブには、システムコールの実行開始/終了時や、カーネルfunctionの実行開始時/終了時などを指定でき、実行回数や実行時間を保存しておくことができます。

詳しくはhttps://www.ibm.com/developerworksを参照のこと。

例えば、実行回数や実行時間を計測したいときは以下のように計測することができます。

実行回数計測のstapスクリプト

vagrant@debian-jessie:~$ sudo stap profile_count.stp -c "ls"
================================================ Syslog Monitoring Started
bin  bonnie++-1.03e  fio_benchmark  gperftool  iozone  karino  orion  perf.data  perf.data.old  read  src  test_bonnie  test_iozone  tmp  vboxguest  write
97 ls(12251) htree_dirblock_to_tree
36 ls(12251) ext4_readdir
32 ls(12251) ext4fs_dirhash
25 stapio(12251) ext4_map_blocks
20 stapio(12251) ext4_find_entry
20 ls(12251) mmap_region
...
================================================ end

実行時間計測のstapスクリプト

vagrant@debian-jessie:~$ sudo stap profile_time.stp -c "ls"
================================================ Syslog Monitoring Started
bin  bonnie++-1.03e  fio_benchmark  gperftool  iozone  karino  orion  perf.data  perf.data.old  read  src  test_bonnie  test_iozone  tmp  vboxguest  write
253 ls(12594) htree_dirblock_to_tree
227 stapio(12594) new_sync_read
175 ls(12594) __ext4_read_dirblock
40 stapio(12592) __fput
25 ls(12594) ext4fs_dirhash
24 ls(12594) __do_page_cache_readahead
...
================================================ end

欲張って全プローブを計測!とかやると死ぬので、自分が見たい範囲を上手く指定してあげるのがポイントです。

また、これを使うためには、カーネルのシンボル情報が必要なので、aptで取得する、もしくは自分でカーネルビルドする必要があります。

カーネル空間で動くコードを読む

遅い部分がわかりました!

だからなんだって感じですね。

Linux kernelを持ってきて、コードを読みます。

apt

Linux kernelも、aptで取得できます。

以下のように、linux-sourceをインストールすると、/usr/srcにtar.xzファイルができます。

そうでなければ、https://www.kernel.org/からコードを持ってきます。

vagrant@debian-jessie:/usr/src$ sudo apt-cache search linux-source
    linux-source-3.16 - Linux kernel source for version 3.16 with Debian patches
    linux-source - Linux kernel source (meta-package)

vagrant@debian-jessie:/usr/src$ sudo apt-get install linux-source-3.16
vagrant@debian-jessie:/usr/src$ ls -l
total 79980
drwxr-xr-x  6 root     4096 Dec  1 18:05 .
drwxr-xr-x 10 root     4096 Jun 22 03:11 ..
-rw-r--r--  1 root 81872836 Nov  9 23:46 linux-source-3.16.tar.xz  <- これ

grep

「コードは手には入ったけど、一体これ、どこから読めば....」と、途方に暮れることでしょう。

そんな時は、迷わずgrep。

straceで目をつけたシステムコールを探して、そこから読んでいくのがいいでしょう。

システムコールは、SYSCALL_DEFINEとかで探すと一発で出てきます。

vagrant@debian-jessie:/usr/src$ ag SYSCALL_DEFINE linux-source-3.16/

    fs/read_write.c:280:SYSCALL_DEFINE3(lseek, unsigned int, fd, off_t, offset, unsigned int, whence)
    fs/read_write.c:299:COMPAT_SYSCALL_DEFINE3(lseek, unsigned int, fd, compat_off_t, offset, unsigned int, whence)
    fs/read_write.c:306:SYSCALL_DEFINE5(llseek, unsigned int, fd, unsigned long, offset_high,
    fs/read_write.c:560:SYSCALL_DEFINE3(read, unsigned int, fd, char __user *, buf, size_t, count)
    fs/read_write.c:575:SYSCALL_DEFINE3(write, unsigned int, fd, const char __user *, buf,
    fs/read_write.c:592:SYSCALL_DEFINE4(pread64, unsigned int, fd, char __user *, buf,
    fs/read_write.c:612:SYSCALL_DEFINE4(pwrite64, unsigned int, fd, const char __user *, buf,
    fs/read_write.c:883:SYSCALL_DEFINE3(readv, unsigned long, fd, const struct iovec __user *, vec,
    fs/read_write.c:903:SYSCALL_DEFINE3(writev, unsigned long, fd, const struct iovec __user *, vec,
    fs/read_write.c:929:SYSCALL_DEFINE5(preadv, unsigned long, fd, const struct iovec __user *, vec,
...

カーネル空間におけるコードの挙動を把握する

しばらくコード読んでるとだんだん辛い気持ちになってくるので、そんな時は気分転換を兼ねて、ツールでコードの挙動を把握します。

systemtap

計測で使ったsystemtap、挙動を確認するためにもかなり役に立ちます。

例えば、以下のようにカーネルfunctionのcall graphを出力することができます。

systemtap/examplesを見ると、いろいろサンプルがあるので、他にも便利な使い方がありそうです。

call_graphを出力するstapスクリプト

vagrant@debian-jessie:~$ sudo stap call_graph.stp -c "ls"
bin  bonnie++-1.03e  fio_benchmark  gperftool  iozone  karino  orion  perf.data  perf.data.old  read  src  test_bonnie  test_iozone  tmp  vboxguest  write
     0 stapio(12918):->ext4_follow_link
     4 stapio(12918):<-ext4_follow_link
     0 stapio(12918):->ext4_file_open
     2 stapio(12918):<-ext4_file_open
     0 stapio(12918):->ext4_getattr
     3 stapio(12918): ->ext4_has_inline_data
     5 stapio(12918): <-ext4_has_inline_data
     6 stapio(12918):<-ext4_getattr
     0 stapio(12918):->ext4_release_file
     1 stapio(12918):<-ext4_release_file
     0 systemd-journal(143):->set_page_dirty page=0xffffea00003cb278
     6 systemd-journal(143): ->__set_page_dirty_no_writeback page=0xffffea00003cb278
     9 systemd-journal(143): <-__set_page_dirty_no_writeback return=0x1
    10 systemd-journal(143):<-set_page_dirty return=0x1
     0 rs:main Q:Reg(536):->ext4_file_write_iter
     6 rs:main Q:Reg(536): ->ext4_dirty_inode
     9 rs:main Q:Reg(536):  ->__ext4_journal_start_sb
    11 rs:main Q:Reg(536):   ->ext4_journal_check_start
    13 rs:main Q:Reg(536):   <-ext4_journal_check_start
    16 rs:main Q:Reg(536):  <-__ext4_journal_start_sb
    18 rs:main Q:Reg(536):  ->ext4_mark_inode_dirty
    21 rs:main Q:Reg(536):   ->ext4_reserve_inode_write
    25 rs:main Q:Reg(536):    ->ext4_get_inode_loc
    27 rs:main Q:Reg(536):     ->__ext4_get_inode_loc
    30 rs:main Q:Reg(536):      ->ext4_get_group_desc
.....

kgdb

カーネルのコードでもgdbを使ってデバッグしたいとき、カーネルデバッガであるkgdbを使います。

これは2つのマシン(デバッグされる対象のマシンと、gdbを実行するマシン)を、シリアルポートで繋いでデバッグを実行します。

VirtualBoxで2つ仮想マシンを立ててデバッグをやっているkgdb-with-virtualbox-debug-live-kernelが最も参考になりました。

ぶっちゃけめんどくさいです。

カーネルビルドしなきゃいけないし、grub書き換えなきゃいけないし、なぜかbreak point効かない場所あるし、時々落ちるし。

ちょっとLinuxカーネル読んだり、カーネルモジュール弄ったりしたいなってレベルでは、ここまでする必要はないかな。。

まとめ

Linuxでコードを追うときに便利なツールたちを紹介しました。

コードを読むだけでなく、計測のやり方や挙動を把握するやり方を知ると、コードをより深く理解できるきっかけになるかもしれません。

明日は、僕の右隣に座っているiizukakさんの「Hierarchical Temporal Memory を学ぶ」です。お楽しみに。