gihyo.jpサイトのロゴ

BSD界隈四方山話

第89回DTraceの使い方 その9

2017-03-03

アプリケーションの分析

コマンドやサーバレベルの動作を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についていろいろ話をしたいといった場合によい機会になると思います（このチュートリアルの講師の方は日本語も喋れますので、コミュニケーションは取りやすいと思います⁠）⁠。

※ ここに掲載したサンプルスクリプトは"DTrace Dynamic Tracing In Oracle Solaris, Mac OS X & FreeBSD", by Brendan Gregg and Jim Mauro P.568、P.569、P.662より抜粋したものです（一部内容を変更してあるほか、FreeBSDで実行した結果を掲載しています⁠）⁠。

勉強会

第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時間ほどの発表資料を作成していただき発表をお願いできればと思います。

おすすめ記事

記事・ニュース一覧