最近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
