アプリケーションの分析
コマンドやサーバレベルの動作をDTraceを使って追っていくことができます。通常はログを解析することでこうした作業を行いますが、DTraceを使うとログを解析するといったことをしなくても動作を追っていくことができます。
たとえば次のようにdtrace(1)コマンドを実行すると、HTTPサーバ(ここではnginx)がオープンしたファイルとその回数を知ることができます。結局、ファイルを開くときはopen(2)システムコールが呼ばれるので、これをプロバイダに指定してモニタリングすることで情報を集めることができるわけです。
図 nginxの開いたファイルをトレース
# dtrace -n 'syscall::open*:entry /execname=="nginx"/{@[copyinstr(arg1)]=count()}'
dtrace: description 'syscall::open*:entry ' matched 6 probes
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x100000) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x100000) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x100000) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x100000) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x100000) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x100000) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x0) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x100000) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x100000) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x100000) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 3 (ID 58065: syscall:freebsd:open:entry): invalid address (0x100000) in action #2 at DIF offset 12
^C
/Users/daichi/Documents/fdt/20170220/typescript.html 1
/Users/daichi/Documents/fdt/20170227/typescript.html 1
/dev/null 1
/dev/crypto 3
/etc/libmap.conf 3
/lib/libc.so.7 3
/lib/libcrypt.so.5 3
/lib/libcrypto.so.8 3
/lib/libthr.so.3 3
/lib/libz.so.6 3
/usr/lib/libssl.so.8 3
/usr/local/etc/nginx/mime.types 3
/usr/local/etc/nginx/nginx.conf 3
/usr/local/lib/libpcre.so.1 3
/var/log/nginx/access.log 3
/var/run/ld-elf.so.hints 3
/var/run/nginx.pid 3
/var/log/nginx/error.log 6
#
たとえば次のようにdtrace(1)コマンドを実行するとsshd(1)経由でシステムにログインしたユーザを追うことができます。ユーザがログインしたタイミングでsshd(8)がchdir(2)を実行してホームディレクトリをカレントディレクトリに設定するので、これを認識してログインを捕捉しています。
図 カレントディレクトリの設定を利用してsshd(8)経由のログインを捕捉
# dtrace -n 'syscall::chdir:entry /execname=="sshd"/{printf ("UID:%d %s",uid,copyinstr(arg0))}'
dtrace: description 'syscall::chdir:entry ' matched 2 probes
CPU ID FUNCTION:NAME
1 62589 chdir:entry UID:0 /
0 62589 chdir:entry UID:0 /
1 62589 chdir:entry UID:1002 /home/daichi
0 62589 chdir:entry UID:0 /
1 62589 chdir:entry UID:0 /
1 62589 chdir:entry UID:0 /
0 62589 chdir:entry UID:0 /
1 62589 chdir:entry UID:1002 /home/daichi
1 62589 chdir:entry UID:0 /
0 62589 chdir:entry UID:0 /
1 62589 chdir:entry UID:1002 /home/daichi
chdir(2)をモニタリングしてカレントディレクトリの設定(ディレクトリの移動)を捕捉する方法は以前取り上げていますが、このchdir(2)をトレースする方法はなかなか便利な方法です。chdir(2)が呼ばれるときは何か意味があって呼ばれることになるので、ここを引っかけることで結構欲しいタイミングでデータを得ることができます。
次のスクリプトはscp(1)コマンドをトレースしてコピー状況を報告するスクリプトです。scp(1)でファイルをネットワーク越しにコピーする場合でもwrite(2)が呼ばれますので、これを利用してモニタリングを実施し、コピー状況を表示させています。
リスト scpwatcher.d
#!/usr/sbin/dtrace -qs
inline int stdout = 1;
syscall::write:entry
/execname=="scp"&&arg0==stdout/
{
printf("%s\n",copyinstr(arg1));
}
実行すると次のような結果が得られます。scp(1)コマンドが出力しているようなデータをDスクリプト側で得られることがわかると思います。
図 scpwatcher.dでscp(1)をトレースした結果
# ./scpwatcher.d
100m 0% 0 0.0KB/s --:-- ETA
100m 13% 13MB 13.0MB/s 00:06 ETA
100m 25% 26MB 13.0MB/s 00:05 ETA
100m 37% 37MB 12.8MB/s 00:04 ETA
100m 48% 49MB 12.7MB/s 00:04 ETA
100m 60% 61MB 12.6MB/s 00:03 ETA
100m 71% 72MB 12.5MB/s 00:02 ETA
100m 82% 83MB 12.3MB/s 00:01 ETA
100m 94% 95MB 12.3MB/s 00:00 ETA
100m 100% 100MB 12.5MB/s 00:08
DTraceを使ってトレースを実行すると、使い方によってはすごくシステムが重くなるので困ったことになりますが、トレースが目的であればそこはそれほど気にならないと思いますし、パフォーマンスへの影響を計測しつつ組み立てていけば、運用サーバでも使えないことはないと思います。
システムコールはさまざまなコマンドやサーバが使うことになりますので、あまり考えないでデータを集計すると膨大なデータを集めることになりかねません。欲しい対象に絞り込んでトレースしていくところがポイントです。
DTraceに関してはAsiaBSDCon 2017の1日目にチュートリアル「T1: DTrace for Developers: no more printfs - George Neville-Neil 」が開催されますので、DTraceをもっと知りたい場合には参加を検討してはいかがでしょうか。DTraceに関するまとまった知識をまとめて得ることができますので、これからDTraceを学びたい、これまで学んできたDTraceについてもう一度復習したい、講師とDTraceについていろいろ話をしたいといった場合によい機会になると思います(このチュートリアルの講師の方は日本語も喋れますので、コミュニケーションは取りやすいと思います) 。
勉強会
第61回 3月23日(木) 19:00- FreeBSD勉強会:リキャップ・ザ・AsiaBSDCon 2017 ~日本語でふりかえるABC~
2017年3月9~12日まで東京でAsiaBSDCon 2017 が開催される予定です。ぜひこのカンファレンスにご参加いただきたいわけなのですが、なかにはどうしても仕事の都合で参加できなかったとか、正直英語がよくわからなかったとか、そういった方もいらっしゃるのではないかと思います。
3月のFreeBSD勉強会では、AsiaBSDCon 2017のあとというこのタイミングを活かして、AsiaBSDCon 2017の発表内容を振り返ってみよう、というのをやってみようと思います。AsiaBSDConに参加しているにもかかわらず、これまで一度もプロシーディングを読み返したことすらないというあなた、ぜひプロシーディングを持参してご参加ください :) AsiaBSDConに参加できなかったというあなたも、この機会をお見逃しなく(できればAsiaBSDConそのものに参加した方が絶対的によいです、あしからず) 。
FreeBSD勉強会 発表者募集
FreeBSD勉強会では発表者を募集しています。FreeBSDに関して発表を行いたい場合、@daichigoto までメッセージをお願いします。1時間半~2時間ほどの発表資料を作成していただき発表をお願いできればと思います。