| ナビゲーションリンクをスキップ | |
| 印刷ビューの終了 | |
|
DTrace ユーザーガイド Oracle Solaris 10 8/11 Information Library (日本語) |
| ナビゲーションリンクをスキップ | |
| 印刷ビューの終了 | |
|
|
DTrace ユーザーガイド Oracle Solaris 10 8/11 Information Library (日本語) |
この節では、ユーザープロセスアクティビティーのトレースに役立つ DTrace 機能に注目し、例を挙げながらその使用法について説明します。
DTrace プローブは、Solaris カーネル内で実行されます。プローブは、サブルーチン copyin() または copyinstr() を使って、ユーザープロセスのデータをカーネルのアドレス空間へコピーします。
たとえば、次のような write() システムコールがあるとします。
ssize_t write(int fd, const void *buf, size_t nbytes);
では、write システムコールに渡される文字列の内容を出力するには、どうしたらよいでしょうか。次に、正しくない D プログラムの例を示します。
syscall::write:entry
{
printf("%s", stringof(arg1)); /* incorrect use of arg1 */
}
このスクリプトを実行すると、次のようなエラーメッセージが出力されます。
dtrace: error on enabled probe ID 1 (ID 37: syscall::write:entry): \
invalid address (0x10038a000) in action #1
arg1 変数には、システムコールを実行しているプロセス内のメモリーを参照するアドレスを指定します。サブルーチン copyinstr() を使って、このアドレスの文字列を読み取ります。printf() アクションを使って、結果を記録します。
syscall::write:entry
{
printf("%s", copyinstr(arg1)); /* correct use of arg1 */
このスクリプトの出力から、write システムコールに渡されるすべての文字列を確認できます。
サブルーチン copyin() と copyinstr() では、一度も使ったことがないユーザーアドレスからの読み取りは実行できません。アドレスが含まれているページが、過去に一度もアクセスされたことがないと、たとえそのアドレスが有効であっても、エラーが起きる可能性があります。次の例で考えてみてください。
# dtrace -n syscall::open:entry'{ trace(copyinstr(arg0)); }'
dtrace: description 'syscall::open:entry' matched 1 probe
CPU ID FUNCTION:NAME
dtrace: error on enabled probe ID 2 (ID 50: syscall::open:entry): invalid address
(0x9af1b) in action #1 at DIF offset 52
前の例の出力では、このアプリケーションが正常に動作していて、arg0 に指定されたアドレスは有効です。しかし、arg0 に指定されたアドレスは、対応するプロセスがまだ一度もアクセスしたことのないページを参照しています。この問題を解決するには、カーネルまたはアプリケーションでデータが使用されるのを待ってから、データのトレースを開始する必要があります。たとえば、システムコールが復帰して、copyinstr() が適用されるまで待ちます。次の例を参照してください。
# dtrace -n syscall::open:entry'{ self->file = arg0; }' \ -n syscall::open:return'{ trace(copyinstr(self->file)); self->file = 0; }'
dtrace: description 'syscall::open:entry' matched 1 probe
CPU ID FUNCTION:NAME
2 51 open:return /dev/null
write システムコールの呼び出しをすべてトレースすると、結果が際限なく出力されます。write() 関数の呼び出しのたびに、dtrace コマンドは、出力表示のため write() 関数を呼び出します。このフィードバックループは、dtrace コマンドの干渉によって望ましくないデータが出力される一例です。この動作を防ぐには、次の例のような述語を使用します。
syscall::write:entry
/pid != $pid/
{
printf("%s", stringof(copyin(arg1, arg2)));
}
$pid マクロ変数は、プローブを有効にしたプロセスのプロセス ID に展開されます。pid 変数には、プローブが起動した CPU 上でスレッドを実行していたプロセスのプロセス ID が入ります。述語 /pid != $pid/ を使用すれば、このスクリプトの実行に関連したすべてのイベントをトレースしないようにできます。
syscall プロバイダでは、すべてのシステムコールの開始 (entry) と終了 (return) をトレースできます。prstat(1M) コマンドを使用すると、プロセスの動作を確認できます。
$ prstat -m -p 31337 PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/NLWP 13499 user1 53 44 0.0 0.0 0.0 0.0 2.5 0.0 4K 24 9K 0 mystery/6
この例では、あるプロセスが多くのシステム時間を消費しています。この動作の原因の 1 つとして考えられるのは、このプロセスが大量のシステムコールを実行しているのではないかということです。コマンド行から、一番頻繁に呼び出されているシステムコールを調べる単純な D プログラムを実行してみましょう。
# dtrace -n syscall:::entry'/pid == 31337/{ @syscalls[probefunc] = count(); }'
dtrace: description 'syscall:::entry' matched 215 probes
^C
open 1
lwp_park 2
times 4
fcntl 5
close 6
sigaction 6
read 10
ioctl 14
sigprocmask 106
write 1092
このレポートから、write() 関数へのシステムコールが多数存在することがわかります。syscall プロバイダを使って、すべての write() システムコールの呼び出し元について詳しく調べることができます。
# dtrace -n syscall::write:entry'/pid == 31337/{ @writes[arg2] = quantize(); }'
dtrace: description 'syscall::write:entry' matched 1 probe
^C
value ------------- Distribution ------------- count
0 | 0
1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1037
2 |@ 3
4 | 0
8 | 0
16 | 0
32 |@ 3
64 | 0
128 | 0
256 | 0
512 | 0
1024 |@ 5
2048 | 0
このプロセスは、比較的少量のデータで、多数の write() システムコールを実行しています。
ustack() アクションは、ユーザーのスレッドのスタックをトレースします。多数のファイルを開くプロセスがあるとします。このプロセスは、ときどき open() システムコールに失敗します。この場合、問題のある open() を実行するコードパスを探すには、ustack() アクションを使用します。
syscall::open:entry
/pid == $1/
{
self->path = copyinstr(arg0);
}
syscall::open:return
/self->path != NULL && arg1 == -1/
{
printf("open for '%s' failed", self->path);
ustack();
}
このスクリプトでは、マクロ変数 $1 も使用されています。このマクロ変数には、dtrace コマンド行に最初に指定されたオペランドの値が入ります。
# dtrace -s ./badopen.d 31337
dtrace: script './badopen.d' matched 2 probes
CPU ID FUNCTION:NAME
0 40 open:return open for '/usr/lib/foo' failed
libc.so.1`__open+0x4
libc.so.1`open+0x6c
420b0
tcsh`dosource+0xe0
tcsh`execute+0x978
tcsh`execute+0xba0
tcsh`process+0x50c
tcsh`main+0x1d54
tcsh`_start+0xdc
ustack() アクションは、スタックのプログラムカウンタ (PC) の値を記録します。すると、dtrace コマンドにより、プロセスのシンボルテーブルが検索され、PC 値がシンボル名に解決されます。dtrace コマンドが、PC 値を解決できない場合は、16 進整数として出力します。
ustack() データに出力書式が設定される前にプロセスが終了したり、強制終了されたりすると、dtrace コマンドは、スタックトレース内の PC 値をシンボル名に変換できなくなる可能性があります。この場合、dtrace コマンドは、これらの値を 16 進整数として表示します。この制限を回避するには、-dtrace コマンドの -c オプションや p オプションを使って、対象プロセスを指定します。プロセス ID やコマンドがあらかじめわかっていない場合は、次のような D プログラムで制限を回避できます。次の例では、open システムコールプローブを使用しています。この方法は、ustack アクションを使用するあらゆるスクリプトで使用できます。
syscall::open:entry
{
ustack();
stop_pids[pid] = 1;
}
syscall::rexit:entry
/stop_pids[pid] != 0/
{
printf("stopping pid %d", pid);
stop();
stop_pids[pid] = 0;
}
このスクリプトは、プロセス内のスレッドに ustack() アクションが適用されている場合、プロセスを、その終了直前に停止します。この方法を利用すれば、dtrace コマンドで PC 値をシンボル名に解決できます。動的な変数がクリアされたら、stop_pids[pid] の値をゼロ (0) に設定します。
pid プロバイダでは、プロセス内の任意の命令をトレースできます。大半のプロバイダとは異なり、pid プローブは、D プログラム内のプローブ記述で、オンデマンドで作成されます。
pid プロバイダのもっとも単純な操作モードは、fbt プロバイダにとってのユーザー空間に似ています。以下は、ある関数の開始 (entry) と終了 (return) をすべてトレースするプログラム例です。マクロ変数 $1 は、コマンド行内の最初のオペランドに展開されます。このマクロ変数は、トレース対象のプロセスのプロセス ID と同じです。マクロ変数 $2 は、コマンド行内の 2 番目のオペランドに展開されます。このマクロ変数は関数名になっています。すべての関数呼び出しは、この関数からトレースされます。
例 4-3 userfunc.d: ユーザー関数の開始 (entry) と終了 (return) のトレース
pid$1::$2:entry
{
self->trace = 1;
}
pid$1::$2:return
/self->trace/
{
self->trace = 0;
}
pid$1:::entry,
pid$1:::return
/self->trace/
{
}
このスクリプトからは、次のような結果が出力されます。
# ./userfunc.d 15032 execute dtrace: script './userfunc.d' matched 11594 probes 0 -> execute 0 -> execute 0 -> Dfix 0 <- Dfix 0 -> s_strsave 0 -> malloc 0 <- malloc 0 <- s_strsave 0 -> set 0 -> malloc 0 <- malloc 0 <- set 0 -> set1 0 -> tglob 0 <- tglob 0 <- set1 0 -> setq 0 -> s_strcmp 0 <- s_strcmp ...
pid プロバイダは、すでに実行中のプロセスに対してしか使用できません。$target マクロ変数と dtrace の -c オプションおよび -p オプションを使用すると、dtrace 機能により、注目するプロセスを作成し測定できます。次の D スクリプトでは、特定の従属プロセスによって実行される libc 関数呼び出しの内訳がわかります。
pid$target:libc.so::entry
{
@[probefunc] = count();
}
次のコマンドを実行すると、date(1) コマンドによって実行されるこの種の呼び出しの内訳がわかります。
# dtrace -s libc.d -c date dtrace: script 'libc.d' matched 2476 probes Fri Jul 30 14:08:54 PDT 2004 dtrace: pid 109196 has exited pthread_rwlock_unlock 1 _fflush_u 1 rwlock_lock 1 rw_write_held 1 strftime 1 _close 1 _read 1 __open 1 _open 1 strstr 1 load_zoneinfo 1 ... _ti_bind_guard 47 _ti_bind_clear 94
pid プロバイダでは、任意のユーザー関数内の任意の命令をトレースできます。pid プロバイダは、必要に応じて、関数内の各命令に対して 1 つずつプローブを作成します。各プローブの名前は、関数内の対応する命令のオフセット (16 進整数) になります。PID 123 のプロセス内にあるモジュール bar.so の関数 foo で、オフセット 0x1c にある命令に関連したプローブを有効にするには、次のコマンドを使用します。
# dtrace -n pid123:bar.so:foo:1c
関数 foo 内のプローブを、各命令用のプローブも含めてすべて有効にするには、次のコマンドを使用します。
# dtrace -n pid123:bar.so:foo:
次の例は、pid プロバイダと投機トレースを組み合わせて、関数内のすべての命令をトレースする方法を示しています。
例 4-4 errorpath.d: ユーザー関数呼び出しのエラーパスをトレース
pid$1::$2:entry
{
self->spec = speculation();
speculate(self->spec);
printf("%x %x %x %x %x", arg0, arg1, arg2, arg3, arg4);
}
pid$1::$2:
/self->spec/
{
speculate(self->spec);
}
pid$1::$2:return
/self->spec && arg1 == 0/
{
discard(self->spec);
self->spec = 0;
}
pid$1::$2:return
/self->spec && arg1 != 0/
{
commit(self->spec);
self->spec = 0;
}
errorpath.d を実行すると、このスクリプトの出力は次のようになります。
# ./errorpath.d 100461 _chdir dtrace: script './errorpath.d' matched 19 probes CPU ID FUNCTION:NAME 0 25253 _chdir:entry 81e08 6d140 ffbfcb20 656c73 0 0 25253 _chdir:entry 0 25269 _chdir:0 0 25270 _chdir:4 0 25271 _chdir:8 0 25272 _chdir:c 0 25273 _chdir:10 0 25274 _chdir:14 0 25275 _chdir:18 0 25276 _chdir:1c 0 25277 _chdir:20 0 25278 _chdir:24 0 25279 _chdir:28 0 25280 _chdir:2c 0 25268 _chdir:return
|