FreeBSD 7.1へようこそ

第4回 DTraceを使おう

この記事を読むのに必要な時間:およそ 3 分

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

リスト2 etimedout.d

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に,ますます期待したい。

脱線になるが,筆者の研究室では「専用ハードウェアによる高速・低消費電力処理」というのを研究のひとつの目玉にしており,消費電力量(単位はジュール)で比較してCPUやGPUに圧勝している。処理速度ではなく消費電力量で性能を云々する日が,そして消費電力量プロバイダ(energy?)がDTraceに実装される日を夢見ている。

著者プロフィール

三田吉郎(みたよしお)

東京大学 大学院工学系研究科 電気系工学専攻准教授。講義「電気磁気学」「わかる電子回路」やマイクロマシン研究の傍ら,FreeBSDの普及,開発に尽力する。FreeBSD ports committer。国際派を自任し,2007~8年9月までフランス国立情報学研究所(INRIA)招聘教授。共著書に「FreeBSD徹底入門」(翔泳社),「FreeBSD Expert」など。