dtrace の stack() でスタックトレースを見る ― 2009年02月28日 00時45分21秒

コードを追っていると目的の動作が何処で起きるのかは比較的わかりやすい。目的の関数はエラー出力や動作から簡単に掴める。しかし、その呼び出し条件を探るとなると一気に難しくなる。

Java 等では、printStackTrace() などの関数があったり、スクリプト言語でも、スタックトレースを出してくれる言語もある。しかし、C 言語となると一筋縄ではいかない。確かにデバッガを使えば判る時もあるが、プログラムの実行が大きく中断されるので、タイマーなどの動作が変わってしまう事がある。

dtrace が提供する言語、D スクリプト言語には stack 関数が用意されている。 


void stack(int nframes)
void stack(void)

例として、swap-in をあげてみよう。名前の通り、関数を見つける事自体は簡単だ。しかし、どのような時に呼ばれるのかを、コードを査読するだけで掴むのは大変だ。そこで、dtrace を使う。 


$ dtrace -n 'fbt::swap_pager_getpages:entry{stack()}'
dtrace: description 'fbt::swap_pager_getpages:entry' matched 1 probe
検査点に入ったときにスタックトレースを出力する。

業とスワップを起こす。そのために幾つかの方法を試してみた。 


$ dd if=/dev/zero of=/mnt/tmpfs/zero bs=10M count=120
$ cat /mnt/tmpfs/zero > /dev/null
$ rm /mnt/tmpfs/zero
$ tar xvf src.tbz2 -C /mnt/tmpfs
$ cd /mnt/tmpfs/src
$ find . -type d | sed 's#^#../copy/#' | xargs mkdir -p
$ sh -c 'for f in `find . -type f`; do cp $f ../copy/$f; done'

上のコマンドを行なっている時に、出てきた出力は以下の様な結果だった。実際には、swap_pager_getpages が呼ばれる度に出力されるので、実際にはもっと大量の出力が出る。 


  1  14739        swap_pager_getpages:entry 
              kernel`vm_thread_swapin+0xcc
              kernel`faultin+0xbf
              kernel`scheduler+0x412
              kernel`mi_startup+0x96
              kernel`0xc045e865

  1  14739        swap_pager_getpages:entry 
              kernel`vm_fault+0x1030
              kernel`trap_pfault+0x15b
              kernel`trap+0x27a
              kernel`0xc0a9e37b

  1  14739        swap_pager_getpages:entry
              kernel`mdstart_swap+0x3e7
              kernel`md_kthread+0x21c
              kernel`fork_exit+0x99
              kernel`0xc0a9e420

  1  14739        swap_pager_getpages:entry 
              kernel`vm_fault+0x1030
              kernel`trap_pfault+0x15b
              kernel`trap+0x417
              kernel`0xc0a9e37b
              kernel`kern_lstat+0x4f
              kernel`lstat+0x2f
              kernel`syscall+0x366
              kernel`0xc0a9e410

wap_pager_getpages:entry
              0xc4d19f54
              kernel`VOP_READ_APV+0x42
              kernel`vn_read+0x2d4
              kernel`dofileread+0x96
              kernel`kern_readv+0x58
              kernel`read+0x4f
              kernel`syscall+0x366
              kernel`0xc0a9e410

  1  14739        swap_pager_getpages:entry 
              kernel`vm_fault+0x1030
              kernel`vm_fault_wire+0x4a
              kernel`vm_map_wire+0x256
              kernel`vslock+0x1d5
              kernel`sysctl_wire_old_buffer+0x5e
              kernel`sysctl_kern_proc+0x178
              kernel`sysctl_root+0x127
              kernel`userland_sysctl+0x134
              kernel`__sysctl+0xde
              kernel`syscall+0x366
              kernel`0xc0a9e410
色々と出てきた。

by uyota [dtrace] [コメント(0)｜トラックバック(0)]