FreeBSD 7.1-RELEASEでは、OpenSolaris由来の強力なシステム監視環境である「DTrace」が使えるようになった。DTraceを使うと、システムの特定の動作を狙い撃ちで取り出して解析することができるので、デバッグやパフォーマンス向上のためのチューニングが楽になるという。今週はこの話題をとりあげよう。

OpenSolarisからの強力な助っ人

DTrace は、Sun Microsystemsによって開発された、システム解析を容易に行なうためのツール群である。たとえば、お使いのFreeBSDシステムが行う特定の動作を「プローブ（probe⁠）⁠」して、プローブが起動した瞬間に指定した解析作業を行って結果を見ることができるスグレモノの開発環境である。DTraceはCommon Development and Distribution Licenseというライセンスの元で配布が認められ、FreeBSD7系列では7.1-RELEASEから配布されるようになった。

一方、GNU General Public Licenceと矛盾するためGPLで保護されたモジュールとCDDLで保護されたモジュールは合法的にリンクできないとGNUの さまざまなライセンスとそれらについての解説というページに記載がある。Linuxではこれが障害となって現在のところ移植は好事家の趣味の範囲を超えられない。ZFS（Zettabyte File System）でも同様の問題が生じるようだが、幸いFreeBSDはCDDLライセンスは問題無く利用できるので、ありがたく利用させてもらおう。

インストールと使い方の学習

DTraceを利用するときに最も役立つ資料は、やはりSun Microsystemsが出す一次資料である。利用にあたっては、 「⁠DTraceユーザーガイド」ならびに、 「⁠Solaris動的トレースガイド」（⁠「⁠Solaris Dynamic Tracing Guide」の日本語訳）を熟読し、常に参照するようにしよう。

FreeBSDでDTraceを使うには、カーネルオプションで、DTraceフックを有効にして、カーネルを再構築する。カーネルソースを展開(DistributionとしてX-Kern-DeveloperやX-Developerなどを選ぶと自動的にKernelのソースが展開されているはず。)したインテル32ビット系CPUのマシン上で、

# cd /sys/i386/conf
# cp GENERIC MYCONF
# echo "options KDTRACE_HOOKS" >> MYCONF
# config MYCONF
Kernel build directory is ../compile/MYCONF
# cd ../compile/MYCONF
# make depend; make WITH_CTF=1 -j 3; make install
# shutdown -r now

とする。コンパイルの際、Compact C Typeを有効に必要があることに注意が必要だ。CTFを有効にし忘れると、チュートリアルにある最も基本的な操作の時点で動作しない。かなりマニアックで「しらんわー」と言いたくなるが仕方がない。

# dtrace -n BEGIN
dtrace: invalid probe specifier BEGIN: "/usr/lib/dtrace/psinfo.d", line 37: syntax error near "uid_t"

のようにエラーが出た人は、カーネルをもう一度作りなおす必要がある。

無事再起動がおわりログインした後、root権限でdtraceモジュールを読み込む。

# kldload dtraceall
This module (opensolaris) contains code covered by the
Common Development and Distribution License (CDDL)
see http://opensolaris.org/os/licensing/opensolaris_license/

ライセンス条項が表示されて、準備OKである。とりあえずチュートリアルのサンプルを順番に実行して、使い方に慣れていくとよいだろう。

【DTrace利用例】システムコールを解析する

DTraceでは、カーネルが特定の動作をしたときをプローブして、そのときのシステムの状況を解析することができる。ユーザプログラムからシステムコールを呼んだとき（entry⁠）⁠、システムコールから帰ってくるとき（return）それぞれについて別々の動作を呼んでシステム解析をする。うまく使えばこれまでいちいちprintf()文を埋め込むといった、デバッグのための余計なコーディングをプログラムにほどこさなくてよいというわけだ。「⁠システム解析」の内容を指示するためには、高級言語でプログラミングを行ないたいところだが、DTrace はその名もずばり、“⁠D⁠”という名の言語でプログラミングをする。

特定のシステムコールが呼ばれた時に動く解析プログラムの基本的な形をリスト1に示す。

/* 関数が呼ばれたとき */
syscall::システムコール名:entry
/ 絞り込み条件 /
{
	解析プログラム本体;
}

/* 関数から戻ってきたとき */
syscall::システムコール名:return
/ 絞り込み条件 /
{
	解析プログラム本体;
}

syscallプロバイダでシステムコールを監視でき、前半の例では特定のシステムコールが呼ばれたとき（entry⁠）⁠、後半の例では特定のシステムコールから戻ってきたとき（return）に、それぞれ有効になる。

ここで試しに、先週の記事でトライしたものの「Operation timed out」エラーが取れなくて撃沈した、データ携帯端末「B-mobile 3G」にプログラム「usb_modeswitch」から命令書き込みを行う様子を監視してみよう。このプログラムでは、「⁠/dev/ugen0.1」というファイルをopenして、そこに対してwrite命令が発行される。監視用のスクリプトをリスト2に示す。

syscall::open:entry
/copyinstr(arg0) == "/dev/ugen0.1"/
{
	self->hook = 1;
	printf("ugen0: open called\n");
}
syscall::open:return
/self->hook == 1/
{
	printf("ugen0: open returned\n");
}

syscall::write:entry
/self->hook == 1/
{
	printf("ugen0: write\n");
	printf("ugen0 writedata: %S\n",stringof(copyin(arg1,arg2)));
	self->hook = 0;
}
syscall::write:return
/errno == 60/
{
	printf ("Operation timed out occurred.\n");
}

リスト2のスクリプトでは、open()関数を呼ぶときと戻るとき、write()関数を呼ぶときと戻るときの、合計4点のプローブポイントを定義している。引数や戻り値をarg0,arg1で参照できるほか、内部変数としてself->変数名 という変数を定義できる。解説の必要も無いほど簡単なプログラムで、以下のようなフックを並べてある。

• まずopen()関数が呼ばれたとき、それが"/dev/ugen0.1"に対するものであったときは通知するとともにフック変数に1を代入
• open()関数から帰ってくるときにフック変数が1であればメッセージを表示
• write()関数が呼ばれたときにフック変数が1であれば書き込む内容を文字列で表示
• write()関数から戻ってくるときに、エラー番号60番(Operation timedout)だった場合メッセージを表示

スクリプトをdtraceに与えるには -s オプションを使う。定義した個数のプローブがdtraceに認識され、イベント起動待ちとなる。

# dtrace -s etimedout.d 
dtrace: script 'etimedout.d' matched 4 probes

ここで、別のxterm端末から先週試した「usb_modeswitch」プログラムでugen0.1に書き込みを行ってみたところ、dtraceがメッセージを表示した。

CPU     ID                    FUNCTION:NAME
  0  38370                       open:entry ugen0 open called

  0  38371                      open:return ugen0 open returned

  0  38368                      write:entry ugen0 write
writedata: USBC\0224Vx \0

  0  38369                     write:return Operation timed out

openのentry→returnは順調に進み、writeのentryまで正常に行われたが、返ってくるところでOperation timed outエラーが出た、ということになる。ちなみに、-q オプションを付けるとフック内の関数の出力のみが表示される。

# dtrace -q -s etimedout.d
ugen0 open called
ugen0 open returned
ugen0 write
writedata: USBC\0224Vx \0
Operation timed out

さてこの結果、先週徹夜で苦労したことと全く同じ挙動を示している。書き込みを試みているが、なぜかOperation timed outが出て書き込みに失敗する、というものだ。ここまでたどりつくのに要した時間は、DTraceスクリプトを作成するのに要した「ものの1分⁠」⁠。printf()をいちいち使うのに比べると、格段に生産性が向上すること請け合いである。

実は、ここでとりあげたsyscallプロバイダでの解析だけなら、truss(1)コマンドを使って、

# truss usb_modeswitch

とすることで、似たような結果を見ることができる。

write(1,"Trying to send the message\n",27)       = 27 (0x1b)
open("/dev/ugen0.1",O_RDWR,05002155324)          = 4 (0x4)
ioctl(4,USB_SET_TIMEOUT,0xbfbee570)              = 0 (0x0)
write(4,"USBC\^R4Vx \0\0\0\M^@\0\f\M^E\^A"...,31) ERR#60 'Operation timed out'
 Sending the message returned error -60, trying to continue ...

trusとの互換部分だけに限ると「なあんだDTrace」となってしまうわけだが、syscallプロバイダの他にも、関数の境界を調べるfbtプロバイダ、ネットワーク監視のmibプロバイダなど、さまざまなプロバイダが用意されており、同じスクリプトの中で有機的に組み合わせて使うことができるのが特長である。ほかにもDTraceでは複数のプログラムをまとめて監視といったことが可能であるし、特定の関数の動作時間を測定して実行速度のチューニング（コラム参照）が容易になるなど、利用可能性は非常に広い。さまざまな可能性を秘めたDTrace に、またこのような新機能を貪欲に実装するFreeBSDに、ますます期待したい。