dwatch コマンドで DTraceの威力を手軽に体感する

DTrace とは

FreeBSD には、Solaris から拝借してきた DTrace と言う仕組みが入っています。
DTrace を使うと、「どっかのプロセスがファイルを何回 openしたか」とか「いくつかのプロセスでsendtoシステムコールでどれだけ時間がかかった」といったシステムの細かな情報をリアルタイムで検知できます。システム全体に(kernel含めて)通過型のブレークポイントを仕込むという感じのことが、プログラムに変更をかけること無く、またシステムにそれほど負荷をかけることなくできてしまうという仕組みです。FreeBSDでは 10 から GENERICカーネルで使えます。

DTrace は /usr/sbin/dtrace というコマンドに D言語(D言語君で有名なあのD言語とはまったく関係ない別もの。awk に近い)でスクリプトを渡して、「このイベントが来たらこんな風にログ出力して」、という処理を記述することで使用します。
そこいらをまず勉強してから使い始めるのが億劫だ、という感じで、強力だとわかりつつも敬遠している人も、私も含めて多かろうと思います。

DTrace をお手軽に試せる dwatch コマンド

FreeBSD 11.2 から、dwatch というコマンドがインストールされるようになりました。このコマンドは、dtrace 機能を D言語を書かずに簡単にお試しできるシェルスクリプトです。
単純な使い方ならこのコマンドだけで十分 DTrace の能力を体感することが出来ます。

例えば、open システムコール呼び出したプロセスをリアルタイムで表示させたい場合はスーパーユーザー権限で（一般ユーザーで実行するとちゃんと sudo を勝手に呼び出してくれます）単に

dwatch

# dwatch open

とすれば

dwatch結果

2018 Dec 18 05:32:49 1001.1001 ibus-ui-gtk3[1425]: /usr/local/libexec/ibus-ui-gtk3
2018 Dec 18 05:32:49 1001.1001 ibus-ui-gtk3[1425]: /usr/local/libexec/ibus-ui-gtk3
2018 Dec 18 05:33:00 0.0 cron[1186]: /usr/sbin/cron -s
2018 Dec 18 05:33:00 0.0 cron[1186]: /usr/sbin/cron -s
2018 Dec 18 05:33:00 0.0 cron[4649]: cron: running job
2018 Dec 18 05:33:00 0.0 cron[4649]: cron: running job

このように、openが実行されたプロセスが次々に表示され続ける状態になります。試しに別の Terminal で cat とかでファイルを開いてみれば、そのプロセスも表示される事が確認できると思います。
dwatch コマンドは Ctrl+C で停止させるまではずっと動き続けて、逐一条件に引っかかったプロセスを表示し続けます。

引っかかったプロセスの親プロセスまでツリーで表示

シェルスクリプト内で呼び出されたプロセスだと、プロセス単独で引っかかってもよくわからなくて、親プロセスが何かが知りたくなります。 -R オプションをつけると、プロセス情報の下に、親子状態をツリー状に表示してくれます。

dwatch_-R

# dwatch -R  open
2018 Dec 18 05:56:16 1001.1001 ibus-ui-gtk3[1425]: /usr/local/libexec/ibus-ui-gtk3
 -+= 01346 1001.1001 /bin/sh /usr/local/etc/xdg/xfce4/xinitrc
  \-+= 01359 1001.1001 xfce4-session
    \-+= 01415 1001.1001 ibus-daemon --xim
      \-+= 01425 1001.1001 /usr/local/libexec/ibus-ui-gtk3

何が検知できるのかの一覧が見たい

dwatchで指定できる検知ポイントの種類としては、probe と profile があります。

probe

probe は DTrace での検知ポイントです。
probe の一覧は、dwatch -l で取得できます。

dwatch_-l

# dwatch -l
ROVIDER:MODULE:FUNCTION:NAME
callout_execute:kernel:none:callout-end
callout_execute:kernel:none:callout-start
dtmalloc::80211com:free
dtmalloc::80211com:malloc
dtmalloc::80211crypto:free
dtmalloc::80211crypto:malloc
dtmalloc::80211dfs:free
dtmalloc::80211dfs:malloc
dtmalloc::80211mesh_gt:free
〜（略）〜

dwatch でコマンドラインで指定した文字列は、前後にワイルドカード指定しているものとみなされます。つまり入力した文字列に部分ヒットした複数のprobeポイントが指定されているのと同じ扱いとなります。

例えば dwatch open と指定した場合にヒットする probe は

dwatch_-l_open

# dwatch -l open
nfscl:nfs4:open:done
nfscl:nfs4:open:start
syscall:freebsd:open:entry
syscall:freebsd:open:return
syscall:freebsd32:open:entry
syscall:freebsd32:open:return

これら全てとなります。

profile

probe をより便利にまとめてdwatchで使用できるようにした D言語 スクリプトが profile です。
profile の一覧は dwatch -Q で表示されます。

dwatch_-Q

# dwatch -Q
    chmod                     errno
    fchmodat                  io
    io-done                   io-start
    ip                        ip-receive
    ip-send                   kill
    lchmod                    nanosleep
    open                      openat
    proc                      proc-create
    proc-exec                 proc-exec-failure
    proc-exec-success         proc-exit
    proc-signal               proc-signal-clear
    proc-signal-discard       proc-signal-send
    proc-status               read
    recv                      recvfrom
    recvmsg                   rw
    sched                     sched-change-pri
    sched-cpu                 sched-dequeue
    sched-enqueue             sched-exec
    sched-lend-pri            sched-load-change
    sched-off-cpu             sched-on-cpu
    sched-preempt             sched-pri
    sched-queue               sched-remain-cpu
    sched-sleep               sched-surrender
    sched-tick                sched-wakeup
    send                      sendmsg
    sendrecv                  sendto
    systop                    tcp
    tcp-accept                tcp-accept-established
    tcp-accept-refused        tcp-connect
    tcp-connect-established   tcp-connect-refused
    tcp-connect-request       tcp-established
    tcp-init                  tcp-io
    tcp-receive               tcp-refused
    tcp-send                  tcp-state-change
    tcp-status                udp
    udp-receive               udp-send
    udplite                   udplite-receive
    udplite-send              vop_create
    vop_lookup                vop_mkdir
    vop_mknod                 vop_readdir
    vop_remove                vop_rename
    vop_rmdir                 vop_symlink
    write

probe よりもわかりやすい大きな括りの項目が多いです。また、openなどの項目も、profileを使った方が、より見やすい表示で出力されるようになっています。

profileを指定した実行は、-Xオプションで

dwatch -X tcp-accept

と実行します。上記コマンドで、待受しているサーバーへのアクセス(established/refused)の結果が逐一表示されます。

詳細は man

より詳細な使い方は man ページを参照すれば出てきます。上記の内容はほとんど man の情報です。
また、dwatch はシェルスクリプトですので、直接読むことも出来ます。
また、profile は /usr/libexec/dwatch 以下に入っているD言語スクリプトです。profile が実際に何をやっているかはここの中を覗けばわかります。

DTrace について

dwatch コマンドでも更に細かく制御したいとなるとD言語を使う必要が出てきます。
そこでとっかかりとして参考になりそうなリンクです。

• 12のワンライナーを見ていくと、DTrace がつかめてくるチュートリアル
  https://wiki.freebsd.org/DTrace/Tutorial

• dtrace の一行野郎集。用途でまとまっていて、コピペ使用だけでも使えるのでは
  https://wiki.freebsd.org/DTrace/One-Liners