カーネル空間までコード追っていこう@Linux
こんにちは。@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 buildctags
コードを読む際、関数の宣言元にジャンプできるようにしておかないと、読んでいくのは苦行すぎます。
一番さっと使えるのは、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を参照のこと。
例えば、実行回数や実行時間を計測したいときは以下のように計測することができます。
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
...
================================================ endvagrant@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を見ると、いろいろサンプルがあるので、他にも便利な使い方がありそうです。
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を使います。
これは２つのマシン(デバッグされる対象のマシンと、gdbを実行するマシン)を、シリアルポートで繋いでデバッグを実行します。
VirtualBoxで2つ仮想マシンを立ててデバッグをやっているkgdb-with-virtualbox-debug-live-kernelが最も参考になりました。
ぶっちゃけめんどくさいです。
カーネルビルドしなきゃいけないし、grub書き換えなきゃいけないし、なぜかbreak point効かない場所あるし、時々落ちるし。
ちょっとLinuxカーネル読んだり、カーネルモジュール弄ったりしたいなってレベルでは、ここまでする必要はないかな。。
まとめ
Linuxでコードを追うときに便利なツールたちを紹介しました。
コードを読むだけでなく、計測のやり方や挙動を把握するやり方を知ると、コードをより深く理解できるきっかけになるかもしれません。
明日は、僕の右隣に座っているiizukakさんの「Hierarchical Temporal Memory を学ぶ」です。お楽しみに。
このブログについて
KLabのゲーム開発・運用で培われた技術や挑戦とそのノウハウを発信します。
広報X
広報Facebookおすすめ
合わせて読みたい
このブログについて
KLabのゲーム開発・運用で培われた技術や挑戦とそのノウハウを発信します。