$shibayu36->blog;

株式会社はてなでエンジニアをしています。プログラミングや読書のことなどについて書いています。

Macでdtrussを使ってシステムコールの実行時間を知る

 最近lsofを使ってportの利用状況をチェックしようとしたら、なぜか数秒固まるということが起こり、drussを使ってどこで止まっているか確かめたのでメモ。


 dtrussというのは、簡単にいえばstraceのOSX版という感じ。どうやって使うかはOSXでもstraceしたい?よろしい、ならばdtrussだ - すがブロあたりをとりあえず見ると分かる。

 ただ、単にdtrussを実行しただけだと、結局どこに時間がかかっていたのかよくわからなかった。manを見ていると、以下のようなオプションがあり、便利そうなので試してみた。

  • -e : それぞれのシステムコールの実行時間をmicrosecondsで出力する
  • -d : コマンド開始からの実行時間をmicrosecondsで出力する


 とりあえず-eと-dオプション付きでlsofでどこに時間がかかっているか調べてみる。

$ sudo dtruss -e -d lsof -i :9200

のコマンドを実行すると、以下のように出力がずらずら並んでいく。

RELATIVE  ELAPSD SYSCALL(args)           = return
      86       3 thread_selfid(0x0, 0x0, 0x0)            = 5203067 0
     116       3 csops(0x0, 0x0, 0x7FFF5D3AAEE8)                 = 0 0
     117       1 issetugid(0x0, 0x0, 0x7FFF5D3AAEE8)             = 0 0
     175       2 shared_region_check_np(0x7FFF5D3A8E28, 0x0, 0x7FFF5D3AAEE8)             = 0 0
     193      14 stat64("/usr/lib/dtrace/libdtrace_dyld.dylib\0", 0x7FFF5D3A9FB8, 0x7FFF5D3AAEE8)                = 0 0
     229      35 open("/usr/lib/dtrace/libdtrace_dyld.dylib\0", 0x0, 0x0)                = 3 0
     234       6 pread(0x3, "\312\376\272\276\0", 0x1000, 0x0)           = 4096 0
     236       2 pread(0x3, "\317\372\355\376\a\0", 0x1000, 0x6000)              = 4096 0
     238       2 fcntl(0x3, 0x3D, 0x7FFF5D3A8320)                = 0 0
     263      23 mmap(0x102873000, 0x2000, 0x5, 0x12, 0x3, 0x6000)               = 0x102873000 0
     267       5 mmap(0x102875000, 0x1000, 0x3, 0x12, 0x3, 0x8000)               = 0x102875000 0
     269       3 mmap(0x102876000, 0x1FC0, 0x1, 0x12, 0x3, 0x9000)               = 0x102876000 0
     285      10 close(0x3)              = 0 0
...

 RELATIVEが経過時間で、ELAPSDがそのシステムコールにかかった時間。これを見ていると、以下のように変に時間がかかっている部分があった。

...
  145547       0 close(0x83B)            = -1 Err#9
  145547       0 close(0x0)              = -1 Err#9
  336047      12 kevent(0x3, 0x0, 0x0)           = 1 0
  336071       8 recvfrom_nocancel(0x6, 0x7FFF5D3AAD90, 0x1C)            = 28 0
  336077       5 recvfrom_nocancel(0x6, 0x7FA652C05540, 0x60)            = 96 0
  336081       3 select_nocancel(0x7, 0x7FFF5D3AADC0, 0x0)               = 0 0
  336084       3 kevent(0x3, 0x7FFF5D3AA890, 0x1)                = 0 0
  336095       9 sendto_nocancel(0x6, 0x7FA652C05220, 0x1C)              = 28 0
  336105       9 close_nocancel(0x3)             = 0 0
  336168      61 open_nocancel("/etc/hosts\0", 0x0, 0x1B6)               = 3 0
  336206       5 fstat64(0x3, 0x7FFF5D3A9EE8, 0x1B6)             = 0 0
...

 実際にkeventにかかった時間は12usなのだけど、経過時間はそこそこ進んでいる。このあたりどういう意味かよくわからなかったけど、keventはイベントを待つようなシステムコールなので、実行時間は少ないけど実際には結構待っている、ということなのかな?と思った。

 ちなみに結局今の知識ではdtrussを読むだけではよく分からなくて、社内でDNSの逆引きが遅いのではという話を聞いたので、lsofで逆引きをしないようにする-nオプションをつけたら非常に高速になった。

$ lsof -n -i :9200

 その話を聞いてよくよく眺めてみると、上の出力で/etc/hostsに対してアクセスしていたり、その後に続いていた出力の中にHost Databaseというワードがあったりと、確かにDNSっぽいシステムコールが発行されているなという気持ちになった。今はまだ使いこなせていないけど、もう少しシステムコールについて詳しくなるといろいろ便利そう。


 また、dtrussは-aオプションで全ての付加情報を出力できる。このオプションをつけると実行時間やプロセスID、システムコールの回数のサマリーなど出してくれる。こちらも便利そうだった。

$ sudo dtruss -a lsof -i :9200
        PID/THRD  RELATIVE  ELAPSD    CPU SYSCALL(args)                  = return
49864/0x4fb107:        51      67      0 thread_selfid(0x0, 0x0, 0x0)            = 5222663 0
49864/0x4fb107:        88       6      1 csops(0x0, 0x0, 0x7FFF53668EE8)                 = 0 0
49864/0x4fb107:        89       3      0 issetugid(0x0, 0x0, 0x7FFF53668EE8)             = 0 0
49864/0x4fb107:       211       6      1 shared_region_check_np(0x7FFF53666E28, 0x0, 0x7FFF53668EE8)             = 0 0
49864/0x4fb107:       237      20     18 stat64("/usr/lib/dtrace/libdtrace_dyld.dylib\0", 0x7FFF53667FB8, 0x7FFF53668EE8)                = 0 0
49864/0x4fb107:       274      36     34 open("/usr/lib/dtrace/libdtrace_dyld.dylib\0", 0x0, 0x0)                = 3 0

...

49864/0x4fb107:    359393      10      2 setitimer(0x0, 0x7FFF536695D0, 0x7FFF536695B0)          = 0 0
49864/0x4fb107:    359397       6      1 sigaction(0xE, 0x7FFF536695A8, 0x7FFF536695D0)          = 0 0

CALL                                        COUNT
bsdthread_register                              1
exit                                            1
fcntl                                           1
fstat64                                         1
getdtablesize                                   1
ioctl                                           1
kqueue                                          1
open_nocancel                                   1
sendmsg_nocancel                                1
setsockopt                                      1
shared_region_check_np                          1
sigaltstack                                     1
sigprocmask                                     1
socketpair                                      1
sysctl                                          1
wait4                                           1
getpid                                          2
issetugid                                       2
open                                            2
pread                                           2
read_nocancel                                   2
setitimer                                       2
sigaction                                       2
thread_selfid                                   2
write_nocancel                                  2
csops                                           3
mmap                                            3
select_nocancel                                 3
sendto_nocancel                                 3
close_nocancel                                  5
recvfrom_nocancel                               5
kevent                                          7
mprotect                                        8
stat64                                         47
close                                        2109