syscall プロバイダでは、すべてのシステムコールの開始 (entry) と終了 (return) をトレースできます。プロセスの動作を把握するときは、まずシステムコールに注目します。特に、そのプロセスがカーネル内で長時間実行されていたり、長時間ブロックされているように見える場合は、そうすることをお勧めします。プロセスがどこで時間を消費しているかを確認するには、prstat(1M) コマンドを使用します。
$ prstat -m -p 31337 PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/NLWP 13499 user1 53 44 0.0 0.0 0.0 0.0 2.5 0.0 4K 24 9K 0 mystery/6 |
この例では、あるプロセスが多くのシステム時間を消費しています。この動作の原因の 1 つとして考えられるのは、このプロセスが大量のシステムコールを実行しているのではないかということです。コマンド行から、一番頻繁に呼び出されているシステムコールを調べる単純な D プログラムを実行してみましょう。
# dtrace -n syscall:::entry'/pid == 31337/{ @syscalls[probefunc] = count(); }' dtrace: description 'syscall:::entry' matched 215 probes ^C open 1 lwp_park 2 times 4 fcntl 5 close 6 sigaction 6 read 10 ioctl 14 sigprocmask 106 write 1092 |
出力結果から、一番頻繁に呼び出されているシステムコールがわかります。この例では、write(2) システムコールが該当します。syscall プロバイダを使って、すべての write() システムコールの呼び出し元について詳しく調べることができます。
# dtrace -n syscall::write:entry'/pid == 31337/{ @writes[arg2] = quantize(arg2); }' dtrace: description 'syscall::write:entry' matched 1 probe ^C value ------------- Distribution ------------- count 0 | 0 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1037 2 |@ 3 4 | 0 8 | 0 16 | 0 32 |@ 3 64 | 0 128 | 0 256 | 0 512 | 0 1024 |@ 5 2048 | 0 |
このプロセスは、比較的少量のデータで、多数の write() システムコールを実行しています。このプロセスの場合、このアンバランスがパフォーマンスの問題の原因になっていると考えられます。これで、システムコールの動作について調査する一般的な方法がわかりました。