賢いdtraceの使い方

皆さんはdtraceをご存じでしょうか？このようなシビレル機能はオトコとしては見逃せません。今回は皆さんにdtraceを紹介しようと思います。

DTraceとは？

Solaris 10に搭載された機能で、名称はDynamic Tracingから来ています。Sunのマニュアルを見ると「動的トレース」と書いてあります。ようはシステムを動かしたままトレースする（システム今どこを実行しているのか、変数がどんな値になっているかなどを調査する）ツールのことです。使いようによっては強力なデバッガーになります。また、プログラムが動作した痕跡（どの関数を何回呼び出したか？など）を集計できることから、性能分析にももってこいです。デバッグやパフォーマンスチューニングでお悩みの皆さんは、是非使ってみてください。 これまで、DTraceのような機能を提供するプログラムはありませんでした。似たようなものがあったとしても、トレースの負荷が高かったりして性能解析には使えないなどの難点があったようです。追跡プログラムとしては、strace（Linux）やtruss（Solaris）がありますが、これらはシステムコールのエントリポイントでしか追跡が出来ないために、カーネルの内部やユーザープログラムまでトレース出来るDTraceとは根本的に異なります。

対応プラットフォーム

DTraceはSPARC版、x64版のSolaris 10で当初開発されました。Solaris 10のオープンソース版であるOpenSolarisでももちろん動作します。また、FreeBSDにも移植しようというプロジェクトもあるようですが、ここを見る限りではまだ開発段階のようです。

DTraceの仕組み

Dtraceは、トレースの対象となるカーネルやユーザープログラムにprobeと呼ばれる観測点を埋め込みます。dtraceモジュールがprobeから情報を収集し、ユーザーがdtraceコマンドを用いて画面上に情報を表示します。その様子を表したのが次の図です。 probeはdtraceが有効になっていないときは、存在しないかもしくはnop命令（no operation：何もしない命令）としてコード上に存在します。そのため、未使用時のシステムへの影響はほとんどありません。probeを有効化（enable）するプログラムをproviderと言います。providerがprobeを有効化しているところを模式的に表したのが次の図です。 dtraceモジュールと同じく、providerもカーネルモジュールとして実装されています。providerにはいくつかの種類があり、その種類によって有効化するprobeの種類が違います。詳しい解説はSunが提供しているマニュアル「DTrace ユーザーガイド」と「Solaris 動的トレースガイド」に譲るとして、ここでは割愛します。少しだけ例をあげると、関数呼び出しをトレースするfbt（function boundary tracing：）やシステムコールのエントリポイントをトレースするsyscall、予めソースコードにprobeを記述することで任意の場所でのトレースを実現するsdt（statically defined tracing）などがあります。Sunのマニュアルは以下のサイトから見ることが出来ます。 Solaris 10 Software Developer Collection - Japanese

D言語

仕組みは分かりましたが、どのようにしてprobeを有効化したり、probeから情報を収集したりすればいいのでしょうか？それは、dtraceコマンドとD言語を使うことで実現します。D言語はC言語ライクなスクリプト言語で、DTrace専用の言語です。例えば次のように記述します。

?

1 2 3 4 5

bash-3.00# cat test.d pid$target:::entry, pid$target:::return { }

このD言語プログラムは、関数の呼び出しとリターンをトレースするもので、次のようにコマンドラインからdtraceコマンドにより実行します。（dtraceコマンドの実行にはroot権限が必要です。）

?

1	bash-3.00# dtrace -F -s test.d -c ls

ここでは例としてlsコマンドをトレースしています。普段よく使うlsコマンドですが、その内部の関数呼び出しの動作を、つぶさに見ることが出来ます。「lsなんて単純なプログラムだよ」と思われていた方も多いのではないかと思います。しかし、dtraceの出力では大変たくさんの関数呼び出しが行われていることが見て取れます。dtraceを使ったことがない方は、是非実行してみてください。 高度なトレースをするには、やはり自分でトレースする対象を絞ったD言語プログラムを書く必要があります。しかし皆さんの中には「そんなの覚えるのは面倒臭い！すぐにDTraceのいいところだけ使いたい！」と思う方もいらっしゃるかも知れません。そんな方には次で紹介するDTrace toolkitが便利です。 D言語をじっくり勉強したい方は、上で紹介したSunのマニュアルを読みましょう。そのうち私のブログでも紹介するつもりですが、それはたぶん先のことになるでしょう。

DTrace toolkit

OpenSolarisで、DTraceToolkitというものを入手することが出来ます。これは、D言語で書かれたプログラム集なのですが、どれも大変便利なものばかりです。 DTrace toolkit page on opensolaris.org D言語はスクリプト言語なので、全てソース付きです。なのでD言語の学習にもうってつけです。（ライセンスはCDDLというOpenSolarisと同じライセンスです。）ファイルはtar.gz形式で配布されているので、展開するだけで使えます。インストーラがついていますが、インストーラを使用すると /opt/DTT ディレクトリへ展開してくれます。このとき、古いファイルがあれば自動的に上書きします。 便利なプログラムばかりなのですが、いくつかピックアップして紹介したいと思います。（DTrace Toolkitには実行結果のサンプルも含まれているのでそちらも参考にしてください。）

dapptrace

ユーザープログラムの動作を追跡するためのプログラムです。どの深さまで追跡するか（プログラムの実行コード内だけなのか？それともライブラリの内部まで追跡するか？）、関数の実行にかかった時間などを追跡できます。 実行例

?

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15

bash-3.00# dapptrace -F -U pwd /opt/DTT CALL(args)               = return   -> ld.so.1:_rt_boot(0x8047F0C, 0x0, 0x8047F10)     -> ld.so.1:_setup(0x8047E20, 0x31B18, 0x3)       -> ld.so.1:setup(0x8047E6C, 0x8047EA4, 0x0)         -> ld.so.1:strrchr(0x8047FEE, 0x2F, 0x0)         <- ld.so.1:strrchr = 111         -> ld.so.1:strrchr(0xD27CB9D7, 0x2F, 0x0)         <- ld.so.1:strrchr = 111         -> ld.so.1:fmap_setup(0x0, 0xD27FB314, 0xD27FB840)         <- ld.so.1:fmap_setup = 125         -> ld.so.1:addfree(0xD27FD3F0, 0xC10, 0x0)         :         :

dappprof

これもユーザープログラムの動作を追跡するためのプログラムです。関数の実行にかかった時間や関数の呼び出し回数について、統計情報を出力します。これを使えばどの関数で時間がかかっているかということが分かりますので、プログラムのチューニングに大変効果を発揮します。 実行例

?

1 2 3 4 5 6 7 8 9 10 11 12

bash-3.00# dappprof -a pwd /opt/DTT   CALL                                                         COUNT a.out            main                                            1 a.out            __fsr                                           1 ld.so.1          _setup                                          1 ld.so.1          atexit_fini                                     1 ld.so.1          _rt_boot                                        1 ld.so.1          setup                                           1 ld.so.1          call_fini                                       1 ld.so.1          addfree                                         1

crash.d

このプログラムはOSの全てプロセスを監視し、コアファイルが生成された時点でそのコアファイルに関する情報を出力します。デーモンがたまに落ちてしまうというような場合に仕掛けておくと便利です。

errinfo

システムコールのリターン時に返ってきたエラーの情報を出力します。デーモンのトラブルシューティングに便利かも知れません。（筆者はまだ実践で使ったことはありませんが。）実際にシステム上で実行してみると、エラーが返りまくってるのが分かります。（以下の実行例は5秒程実行したものですが、たったこれだけなのにこんなにエラーが出てるんですね！） 実行例

?

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29

bash-3.00# errinfo             EXEC          SYSCALL  ERR  DESC       svc.startd           portfs   62  timer expired       svc.startd           portfs   62  timer expired             nscd         lwp_kill    3  No such process             nscd         lwp_kill    3  No such process            xntpd       sigsuspend    4  interrupted system call       svc.startd           portfs   62  timer expired       svc.startd           portfs   62  timer expired            xntpd       sigsuspend    4  interrupted system call       svc.startd           portfs   62  timer expired       svc.startd           portfs   62  timer expired             nscd         lwp_kill    3  No such process             nscd            fcntl   22  Invalid argument            xntpd       sigsuspend    4  interrupted system call       svc.startd           portfs   62  timer expired       svc.startd           portfs   62  timer expired            xntpd       sigsuspend    4  interrupted system call       svc.startd           portfs   62  timer expired       svc.startd           portfs   62  timer expired            xntpd       sigsuspend    4  interrupted system call            snmpd            ioctl   12  Not enough core       svc.startd           portfs   62  timer expired       svc.startd           portfs   62  timer expired             smbd           stat64    2  No such file or directory             smbd           open64    2  No such file or directory             smbd           open64    2  No such file or directory             smbd           stat64    2  No such file or directory            xntpd       sigsuspend    4  interrupted system call

execsnoop

execシステムコール（プログラムの実行）を監視して、実行されたプログラムに関する情報を出力します。使いでは色々ありますね。execsnoopを監視していれば、変なプログラムを実行しているユーザーを突き止める、なんてことも可能です。実行例は、他のホストからtelnetでログインした時のものです。 実行例

?

1 2 3 4 5 6 7 8 9 10 11

bash-3.00# execsnoop   UID    PID   PPID ARGS     0  17728    269 /usr/sbin/in.telnetd     0  17729  17728 pt_chmod 3     0  17730  17728 sh -c eval echo '""'       0  17731  17728 login -p -h 192.168.0.2 -d /dev/pts/4  1001  17731  17728 -tcsh  1001  17732  17731 /usr/sbin/quota  1001  17733  17731 /bin/cat -s /etc/motd  1001  17734  17731 /bin/mail -E

他にもまだまだたくさんプログラムがあるので、皆さんの手で是非試してみてください。 最後に注意点を一つだけ挙げておきます。DTrace Toolkitでは、カーネルやユーザープログラムの内部変数を参照しているものがいくつかあります。ということは、カーネルのバージョンが上がったりすると、動かなくなるプログラムが出てきます。実際、筆者はtcpsnoopやhttpdstat.dなどのプログラムが期待する動作をしないことを確認しています。もしツールキットの中のプログラムがうまく動かない時は、自分で手直ししてみるのも一興かも知れません。