読者です 読者をやめる 読者になる 読者になる

Erlang R15B01 で DTrace(SystemTap) を使ってみる

erlang dtrace systemtap

注意: DTrace まったくわかりません。D 言語(D スクリプト) は書けません。読めません。

とりあえずインストールして動かしてみたよ、程度のレベルです。
DTrace 使ったらこんなに幸せになったよエントリーではありません。

追記

  • 2012-04-04
    • R15B01 が出たので R15B01 に合わせました。

環境

OS
Mac OS X 10.7.3
CPU
Core 2 Duo 1.6 G
Mem
4G

インストール

R15B01 をビルドします。--with-dynamic-trace で dtrace を指定しましょう。

Linux の場合は systemtap を指定しましょう。--prefix の部分はお好きにどうぞ、あと hipe は自分が使う分には余り効果が無いので無効にしています。

$ curl -O http://dl.dropbox.com/u/89936/otp_src_R15B01.tar.gz
$ cd otp_src_R15B01
$ ./configure --prefix=/opt/local/erlang/R15B01 --enable-smp-support \
              --enable-darwin-64bit --enable-kernel-poll --without-javac \ 
              --disable-native-libs --disable-hipe --disable-sctp \
              --enable-threads --with-dynamic-trace=dtrace
$ make
$ sudo make install

これで環境構築は終わりです。

サンプルを見てみる

注意: ファイル等は DTrace だけ表示しています。SystemTap のも同様に入っています。

サンプルは runtime_tools フォルダの examples にあります。

$ cd /opt/local/erlang/maint/lib/erlang/lib/runtime_tools-1.8.7/examples
$ ls
dist.d
driver1.d
efile_drv.d
function-calls.d
garbage-collection.d
memory1.d
messages.d
port1.d
process-scheduling.d
spawn-exit.d
user-probe.d

efile_drv.d を見てみます ... が正直良くわかりません。勉強不足 orz

BEGIN
{
    op_map[1] = "OPEN";
    op_map[2] = "READ";
    op_map[3] = "LSEEK";
    op_map[4] = "WRITE";
    op_map[5] = "FSTAT";
    op_map[6] = "PWD";
    op_map[7] = "READDIR";
    op_map[8] = "CHDIR";
    op_map[9] = "FSYNC";
    op_map[10] = "MKDIR";
    op_map[11] = "DELETE";
    op_map[12] = "RENAME";
    op_map[13] = "RMDIR";
    op_map[14] = "TRUNCATE";
    op_map[15] = "READ_FILE";
    op_map[16] = "WRITE_INFO";
    op_map[19] = "LSTAT";
    op_map[20] = "READLINK";
    op_map[21] = "LINK";
    op_map[22] = "SYMLINK";
    op_map[23] = "CLOSE";
    op_map[24] = "PWRITEV";
    op_map[25] = "PREADV";
    op_map[26] = "SETOPT";
    op_map[27] = "IPREAD";
    op_map[28] = "ALTNAME";
    op_map[29] = "READ_LINE";
    op_map[30] = "FDATASYNC";
    op_map[31] = "FADVISE";
}

erlang*:::aio_pool-add
{
    printf("async I/O pool port %s queue len %d\n", copyinstr(arg0), arg1);
}

erlang*:::aio_pool-get
{
    printf("async I/O pool port %s queue len %d\n", copyinstr(arg0), arg1);
}

erlang*:::efile_drv-entry
{
    printf("efile_drv enter tag={%d,%d} %s%s | %s (%d) | args: %s %s , %d %d (port %s)\n",
	   arg0, arg1,
           arg2 == NULL ? "" : "user tag ",
           arg2 == NULL ? "" : copyinstr(arg2),
           op_map[arg3], arg3,
	   arg4 == NULL ? "" : copyinstr(arg4),
	   arg5 == NULL ? "" : copyinstr(arg5), arg6, arg7,
           /* NOTE: port name in args[10] is experimental */
           (args[10] == NULL) ? 
	       "?" : copyinstr((user_addr_t) args[10]));
}

erlang*:::efile_drv-int*
{
    printf("async I/O worker tag={%d,%d} | %s (%d) | %s\n",
           arg0, arg1, op_map[arg2], arg2, probename);
}

/* efile_drv-return error case */
erlang*:::efile_drv-return
/arg4 == 0/
{
    printf("efile_drv return tag={%d,%d} %s%s | %s (%d) | errno %d\n",
           arg0, arg1,
           arg2 == NULL ? "" : "user tag ",
           arg2 == NULL ? "" : copyinstr(arg2),
           op_map[arg3], arg3,
           arg5);
}

/* efile_drv-return success case */
erlang*:::efile_drv-return
/arg4 != 0/
{
    printf("efile_drv return tag={%d,%d} %s | %s (%d) ok\n",
           arg0, arg1,
           arg2 == NULL ? "" : copyinstr(arg2),
           op_map[arg3], arg3);
}

ちょっと動かしてみる

まずは Erlang VM を起動します
[dtrace] というのが表示されていればおkです。

$ /opt/local/erlang/maint/bin/erl                               
Erlang R15B01 (erts-5.9.1) [source] [64-bit] [smp:2:2] [async-threads:0] [kernel-poll:false] [dtrace]

Eshell V5.9.1  (abort with ^G)
1> 

DTrace を実行する。今回は efile_drv.d

$ sudo dtrace -qs efile_drv.d

Erlang VM 側でファイルを開いて書き込みしてみます。

Eshell V5.9.1  (abort with ^G)
1> {ok, Fd} = file:open("/tmp/spam", [raw, append, binary]).
{ok,{file_descriptor,prim_file,{#Port<0.494>,14}}}
2> file:write(Fd, <<"abcdefg">>).
ok

DTrace 側に以下のようなのが表示されました。

efile_drv enter tag={0,470}  | PWD (6) | args:   , 0 0 (port #Port<0.474>)
async I/O worker tag={0,470} | PWD (6) | efile_drv-int_entry
async I/O worker tag={0,470} | PWD (6) | efile_drv-int_return
efile_drv return tag={0,470}  | PWD (6) ok
efile_drv enter tag={0,471}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/runtime_tools-1.8.7/examples/./erl_scan.beam  , 0 0 (port #Port<0.475>)
async I/O worker tag={0,471} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,471} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,471} user tag  | READ_FILE (15) | errno 2
efile_drv enter tag={0,472}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/kernel-2.15.1/ebin/erl_scan.beam  , 0 0 (port #Port<0.476>)
async I/O worker tag={0,472} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,472} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,472} user tag  | READ_FILE (15) | errno 2
efile_drv enter tag={0,473}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/stdlib-1.18.1/ebin/erl_scan.beam  , 0 0 (port #Port<0.477>)
async I/O worker tag={0,473} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,473} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,473}  | READ_FILE (15) ok
efile_drv enter tag={0,474}  | PWD (6) | args:   , 0 0 (port #Port<0.478>)
async I/O worker tag={0,474} | PWD (6) | efile_drv-int_entry
async I/O worker tag={0,474} | PWD (6) | efile_drv-int_return
efile_drv return tag={0,474}  | PWD (6) ok
efile_drv enter tag={0,475}  | PWD (6) | args:   , 0 0 (port #Port<0.479>)
async I/O worker tag={0,475} | PWD (6) | efile_drv-int_entry
async I/O worker tag={0,475} | PWD (6) | efile_drv-int_return
efile_drv return tag={0,475}  | PWD (6) ok
efile_drv enter tag={0,476}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/runtime_tools-1.8.7/examples/./erl_parse.beam  , 0 0 (port #Port<0.480>)
async I/O worker tag={0,476} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,476} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,476} user tag  | READ_FILE (15) | errno 2
efile_drv enter tag={0,477}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/kernel-2.15.1/ebin/erl_parse.beam  , 0 0 (port #Port<0.481>)
async I/O worker tag={0,477} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,477} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,477} user tag  | READ_FILE (15) | errno 2
efile_drv enter tag={0,478}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/stdlib-1.18.1/ebin/erl_parse.beam  , 0 0 (port #Port<0.482>)
async I/O worker tag={0,478} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,478} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,478}  | READ_FILE (15) ok
efile_drv enter tag={0,479}  | PWD (6) | args:   , 0 0 (port #Port<0.483>)
async I/O worker tag={0,479} | PWD (6) | efile_drv-int_entry
async I/O worker tag={0,479} | PWD (6) | efile_drv-int_return
efile_drv return tag={0,479}  | PWD (6) ok
efile_drv enter tag={0,480}  | PWD (6) | args:   , 0 0 (port #Port<0.484>)
async I/O worker tag={0,480} | PWD (6) | efile_drv-int_entry
async I/O worker tag={0,480} | PWD (6) | efile_drv-int_return
efile_drv return tag={0,480}  | PWD (6) ok
efile_drv enter tag={0,481}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/runtime_tools-1.8.7/examples/./otp_internal.beam  , 0 0 (port #Port<0.485>)
async I/O worker tag={0,481} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,481} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,481} user tag  | READ_FILE (15) | errno 2
efile_drv enter tag={0,482}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/kernel-2.15.1/ebin/otp_internal.beam  , 0 0 (port #Port<0.486>)
async I/O worker tag={0,482} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,482} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,482} user tag  | READ_FILE (15) | errno 2
efile_drv enter tag={0,483}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/stdlib-1.18.1/ebin/otp_internal.beam  , 0 0 (port #Port<0.487>)
async I/O worker tag={0,483} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,483} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,483}  | READ_FILE (15) ok
efile_drv enter tag={0,484}  | PWD (6) | args:   , 0 0 (port #Port<0.488>)
async I/O worker tag={0,484} | PWD (6) | efile_drv-int_entry
async I/O worker tag={0,484} | PWD (6) | efile_drv-int_return
efile_drv return tag={0,484}  | PWD (6) ok
efile_drv enter tag={0,485}  | PWD (6) | args:   , 0 0 (port #Port<0.489>)
async I/O worker tag={0,485} | PWD (6) | efile_drv-int_entry
async I/O worker tag={0,485} | PWD (6) | efile_drv-int_return
efile_drv return tag={0,485}  | PWD (6) ok
efile_drv enter tag={0,486}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/runtime_tools-1.8.7/examples/./erl_internal.beam  , 0 0 (port #Port<0.490>)
async I/O worker tag={0,486} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,486} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,486} user tag  | READ_FILE (15) | errno 2
efile_drv enter tag={0,487}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/kernel-2.15.1/ebin/erl_internal.beam  , 0 0 (port #Port<0.491>)
async I/O worker tag={0,487} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,487} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,487} user tag  | READ_FILE (15) | errno 2
efile_drv enter tag={0,488}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/stdlib-1.18.1/ebin/erl_internal.beam  , 0 0 (port #Port<0.492>)
async I/O worker tag={0,488} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,488} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,488}  | READ_FILE (15) ok
efile_drv enter tag={0,489}  | PWD (6) | args:   , 0 0 (port #Port<0.493>)
async I/O worker tag={0,489} | PWD (6) | efile_drv-int_entry
async I/O worker tag={0,489} | PWD (6) | efile_drv-int_return
efile_drv return tag={0,489}  | PWD (6) ok
efile_drv enter tag={0,490}  | OPEN (1) | args: /tmp/spam  , 6 0 (port #Port<0.494>)
async I/O worker tag={0,490} | OPEN (1) | efile_drv-int_entry
async I/O worker tag={0,490} | OPEN (1) | efile_drv-int_return
efile_drv return tag={0,490}  | OPEN (1) ok
efile_drv enter tag={0,491}  | PWD (6) | args:   , 0 0 (port #Port<0.495>)
async I/O worker tag={0,491} | PWD (6) | efile_drv-int_entry
async I/O worker tag={0,491} | PWD (6) | efile_drv-int_return
efile_drv return tag={0,491}  | PWD (6) ok
efile_drv enter tag={0,492}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/runtime_tools-1.8.7/examples/./io_lib_pretty.beam  , 0 0 (port #Port<0.496>)
async I/O worker tag={0,492} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,492} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,492} user tag  | READ_FILE (15) | errno 2
efile_drv enter tag={0,493}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/kernel-2.15.1/ebin/io_lib_pretty.beam  , 0 0 (port #Port<0.497>)
async I/O worker tag={0,493} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,493} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,493} user tag  | READ_FILE (15) | errno 2
efile_drv enter tag={0,494}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/stdlib-1.18.1/ebin/io_lib_pretty.beam  , 0 0 (port #Port<0.498>)
async I/O worker tag={0,494} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,494} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,494}  | READ_FILE (15) ok
efile_drv enter tag={0,495}  | PWD (6) | args:   , 0 0 (port #Port<0.499>)
async I/O worker tag={0,495} | PWD (6) | efile_drv-int_entry
async I/O worker tag={0,495} | PWD (6) | efile_drv-int_return
efile_drv return tag={0,495}  | PWD (6) ok
efile_drv enter tag={0,496}  | PWD (6) | args:   , 0 0 (port #Port<0.500>)
async I/O worker tag={0,496} | PWD (6) | efile_drv-int_entry
async I/O worker tag={0,496} | PWD (6) | efile_drv-int_return
efile_drv return tag={0,496}  | PWD (6) ok
efile_drv enter tag={0,497}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/runtime_tools-1.8.7/examples/./erl_bits.beam  , 0 0 (port #Port<0.501>)
async I/O worker tag={0,497} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,497} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,497} user tag  | READ_FILE (15) | errno 2
efile_drv enter tag={0,498}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/kernel-2.15.1/ebin/erl_bits.beam  , 0 0 (port #Port<0.502>)
async I/O worker tag={0,498} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,498} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,498} user tag  | READ_FILE (15) | errno 2
efile_drv enter tag={0,499}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/stdlib-1.18.1/ebin/erl_bits.beam  , 0 0 (port #Port<0.503>)
async I/O worker tag={0,499} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,499} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,499}  | READ_FILE (15) ok
efile_drv enter tag={0,500}  | PWD (6) | args:   , 0 0 (port #Port<0.504>)
async I/O worker tag={0,500} | PWD (6) | efile_drv-int_entry
async I/O worker tag={0,500} | PWD (6) | efile_drv-int_return
efile_drv return tag={0,500}  | PWD (6) ok
efile_drv enter tag={0,501}  | PWD (6) | args:   , 0 0 (port #Port<0.505>)
async I/O worker tag={0,501} | PWD (6) | efile_drv-int_entry
async I/O worker tag={0,501} | PWD (6) | efile_drv-int_return
efile_drv return tag={0,501}  | PWD (6) ok
efile_drv enter tag={0,502}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/runtime_tools-1.8.7/examples/./eval_bits.beam  , 0 0 (port #Port<0.506>)
async I/O worker tag={0,502} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,502} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,502} user tag  | READ_FILE (15) | errno 2
efile_drv enter tag={0,503}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/kernel-2.15.1/ebin/eval_bits.beam  , 0 0 (port #Port<0.507>)
async I/O worker tag={0,503} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,503} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,503} user tag  | READ_FILE (15) | errno 2
efile_drv enter tag={0,504}  | READ_FILE (15) | args: /opt/local/erlang/maint/lib/erlang/lib/stdlib-1.18.1/ebin/eval_bits.beam  , 0 0 (port #Port<0.508>)
async I/O worker tag={0,504} | READ_FILE (15) | efile_drv-int_entry
async I/O worker tag={0,504} | READ_FILE (15) | efile_drv-int_return
efile_drv return tag={0,504}  | READ_FILE (15) ok
efile_drv enter tag={0,505}  | PWD (6) | args:   , 0 0 (port #Port<0.509>)
async I/O worker tag={0,505} | PWD (6) | efile_drv-int_entry
async I/O worker tag={0,505} | PWD (6) | efile_drv-int_return
efile_drv return tag={0,505}  | PWD (6) ok
efile_drv enter tag={0,506}  | WRITE (4) | args:   , 14 6 (port #Port<0.494>)
async I/O worker tag={0,506} | WRITE (4) | efile_drv-int_entry
async I/O worker tag={0,506} | WRITE (4) | efile_drv-int_return
efile_drv return tag={0,506}  | WRITE (4) ok

なんとなくわかる気にはなりますが ... 正直わかりません。

感想

DTrace は仕事で Solaris 触ってるときに使おうかなー使おうかなーとおもって結局使いませんでした。そして気付いたら仕事は Linux メインになっていたので触る機会なし。ただ Erlang VM が DTrace(SystemTap) に対応したので、ドキドキワクワクしながら使ってみました。

良くわからないけど覚えたら凄く便利そう、というのが正直な感想です。

DTrace は Oracle が SystemTap は RH が中心になって開発しているっぽいので、当面はゴリゴリ開発されるのだと思います。
Erlang の DTrace は 2008 年頃に一瞬出てきてしぼんでいたのを Basho のメンバーが復活させて最後には otp にまで突っ込むという素敵な方針に。

R15B01 が出たら標準で使えるようになる事もあり、今後は積極的に使っていこうと思います。

Erlang でアプリを書いている以上、I/O 周りとの戦いは終わることはありません。今回がいいきっかけになったと思っております。