第 33 章 ユーザープロセスのトレース
DTrace は、ユーザープロセスの動作を把握するために役立つ非常に強力なツールです。デバッグ時やパフォーマンスの問題の解析時に、あるいはただ複雑なアプリケーションの動作を理解したい場合にも、DTrace は非常に有益です。この章では、ユーザープロセスアクティビティに関する DTrace 機能に注目し、例を挙げながらその使用法について説明します。
サブルーチン copyin() と copyinstr()
DTrace でのプロセスの扱い方は、従来のデバッガや監視ツールとは若干異なっています。従来のツールは、プロセスのスコープ内で実行されます。このため、プログラム変数のポインタの間接参照をユーザー側で行うことができます。これに対して、DTrace プローブは、Solaris カーネル内で実行されます。プロセス内で (プロセスの一部として) 実行されるわけではありません。プロセスデータにアクセスする場合、プローブは、サブルーチン copyin() または copyinstr() を使って、ユーザープロセスデータをカーネルのアドレス空間にコピーする必要があります。
たとえば、次のような write(2) システムコールがあるとします。
ssize_t write(int fd, const void *buf, size_t nbytes);
では、write(2) システムコールに渡される文字列の内容を出力するには、どうしたらよいでしょうか。以下は、正しくない 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 変数には、buf パラメータの値として、システムコールの実行プロセス内のメモリーを参照するアドレスが入ります。このアドレスの文字列を読み取るには、copyinstr() サブルーチンを使用し、その結果を printf() アクションで記録します。
syscall::write:entry
{
printf("%s", copyinstr(arg1)); /* correct use of arg1 */
このスクリプトの出力から、write(2) システムコールに渡されるすべての文字列を確認できます。ただし、以下のような異常な出力が得られる場合もあります。
0 37 write:entry mada��� |
copyinstr() サブルーチンは、入力引数 (NULL で終わっている ASCII 文字列のユーザーアドレス) に対して機能します。しかし、write(2) システムコールに渡されるバッファーが、ASCII 文字列ではなくバイナリデータを参照していることがあります。呼び出し側が意図した文字列だけを出力するには、copyin() サブルーチンを使用します。このサブルーチンの第 2 引数にサイズを指定します。
syscall::write:entry
{
printf("%s", stringof(copyin(arg1, arg2)));
}
stringof 演算子がないと、DTrace は、copyin() を使って取得したユーザーデータを正しく文字列に変換できません。しかし、copyinstr() を使用する場合は、stringof は不要になります。これは、copyinstr が常に string 型を返すからです。
エラーの回避
サブルーチン 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 に指定されたアドレスも有効ですが、対応するプロセスがまだアクセスしたことがないページが参照されています。この問題を解決するには、カーネルまたはアプリケーションでデータが使用されるのを待ってからトレースを開始する必要があります。たとえば、システムコールが復帰して、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
|
dtrace(1M) の干渉の排除
write(2) システムコールの呼び出しをすべてトレースすると、結果が際限なく出力されます。write() の呼び出しのたびに、dtrace(1M) コマンドが出力表示のために write() を呼び出します。このフィードバックループは、dtrace コマンドの干渉によって望ましくないデータが出力される一例です。このような不要なデータのトレースを防ぐには、次の述語を使用します。
syscall::write:entry
/pid != $pid/
{
printf("%s", stringof(copyin(arg1, arg2)));
}
$pid マクロ変数は、プローブを有効にしたプロセスのプロセス ID に展開されます。pid 変数には、プローブが起動した CPU 上でスレッドを実行していたプロセスのプロセス ID が入ります。このため、述語 /pid != $pid/ を使用すれば、このスクリプト自体の実行に関連したイベントをトレースしないようにできます。
syscall プロバイダ
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(2) システムコールが該当します。syscall プロバイダを使って、すべての write() システムコールの呼び出し元について詳しく調べることができます。
# dtrace -n syscall::write:entry'/pid == 31337/{ @writes[arg2] = quantize(arg2); }'
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() アクション
問題をより詳しく調査するときは、特定のプローブが起動したときのプロセススレッドのスタックをトレースするとよいでしょう。ustack() アクションは、ユーザースレッドのスタックをトレースします。たとえば、多数のファイルを開くプロセスがあるとします。このプロセスは、ときどき open(2) システムコールに失敗します。この場合、問題のある 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(1M) コマンド行で指定された最初のオペランドの値が入ります。
# 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(1M) により、プロセスのシンボルテーブルが検索され、PC 値がシンボル名に解決されます。dtrace が PC 値をシンボル名に解決できない場合は、その値は 16 進整数として出力されます。
ustack() データの出力書式が設定される前にプロセスが終了 (強制終了も含む) すると、dtrace が、スタックトレース内の PC 値をシンボル名に変換できない場合があります。この場合、これらの値は 16 進整数で表示されます。この制限を回避するには、-dtrace コマンドの -c オプションや p オプションを使って、対象プロセスを指定します。これらのオプションやその他のオプションの詳細については、第 14 章dtrace(1M) ユーティリティーを参照してください。プロセス ID やコマンドがあらかじめわかっていない場合は、次のような D プログラムで制限を回避できます。
/*
* This example uses the open(2) system call probe, but this technique
* is applicable to any script using the ustack() action where the stack
* being traced is in a process that may exit soon.
*/
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] の値は、動的変数の消去が完了したら、ゼロになります。prun(1) コマンドを使って、停止したプロセスが実行再開するように設定してください。そうしないと、システム上の停止プロセスが蓄積されてしまいます。
uregs[] 配列
uregs[] 配列を使用すると、個々のユーザーレジスタにアクセスできます。以下の表に、uregs[] 配列のインデックスを、Solaris でサポートされているシステムアーキテクチャ別に示します。
表 33–1 SPARC uregs[] 定数|
定数 |
レジスタ |
|---|---|
|
R_G0..R_G7 |
%g0..%g7 汎用レジスタ |
|
R_O0..R_O7 |
%o0..%o7 アウトレジスタ |
|
R_L0..R_L7 |
%l0..%l7 ローカルレジスタ |
|
R_I0..R_I7 |
%i0..%i7 インレジスタ |
|
R_CCR |
%ccr 条件コードレジスタ |
|
R_PC |
%pc プログラムカウンタ |
|
R_NPC |
%npc 次のプログラムカウンタ |
|
R_Y |
%y 乗算/除算レジスタ |
|
R_ASI |
%asi アドレス空間識別レジスタ |
|
R_FPRS |
%fprs 浮動小数点レジスタの状態 |
表 33–2 x86 uregs[] 定数
|
定数 |
レジスタ |
|---|---|
|
R_CS |
%cs |
|
R_GS |
%gs |
|
R_ES |
%es |
|
R_DS |
%ds |
|
R_EDI |
%edi |
|
R_ESI |
%esi |
|
R_EBP |
%ebp |
|
R_EAX |
%eax |
|
R_ESP |
%esp |
|
R_EAX |
%eax |
|
R_EBX |
%ebx |
|
R_ECX |
%ecx |
|
R_EDX |
%edx |
|
R_TRAPNO |
%trapno |
|
R_ERR |
%err |
|
R_EIP |
%eip |
|
R_CS |
%cs |
|
R_ERR |
%err |
|
R_EFL |
%efl |
|
R_UESP |
%uesp |
|
R_SS |
%ss |
AMD64 プラットフォームの uregs 配列には、x86 プラットフォームの内容に加えて、以下の表の要素が含まれます。
表 33–3 amd64 uregs[] 定数|
定数 |
レジスタ |
|---|---|
|
R_RSP |
%rsp |
|
R_RFL |
%rfl |
|
R_RIP |
%rip |
|
R_RAX |
%rax |
|
R_RCX |
%rcx |
|
R_RDX |
%rdx |
|
R_RBX |
%rbx |
|
R_RBP |
%rbp |
|
R_RSI |
%rsi |
|
R_RDI |
%rdi |
|
R_R8 |
%r8 |
|
R_R9 |
%r9 |
|
R_R10 |
%r10 |
|
R_R11 |
%r11 |
|
R_R12 |
%r12 |
|
R_R13 |
%r13 |
|
R_R14 |
%r14 |
|
R_R15 |
%r15 |
すべてのプラットフォームで使用できる別名は、以下の表のとおりです。
表 33–4 共通の uregs[] 定数|
定数 |
レジスタ |
|---|---|
|
R_PC |
プログラムカウンタレジスタ |
|
R_SP |
スタックポインタレジスタ |
|
R_R0 |
最初の復帰コード |
|
R_R1 |
2 番目の復帰コード |
pid プロバイダ
pid プロバイダでは、プロセス内の任意の命令をトレースできます。大半のプロバイダとは異なり、pid プローブは、D プログラム内のプローブ記述で、オンデマンドで作成されます。そのため、ユーザー自身で pid プローブを有効にしないかぎり、dtrace -l を実行しても何も出力されません。
ユーザー関数境界のトレース
pid プロバイダのもっとも単純な操作モードは、fbt プロバイダにとってのユーザー空間に似ています。以下は、ある関数の開始 (entry) と終了 (return) をすべてトレースするプログラム例です。$1 マクロ変数 (コマンド行の最初のオペランド) には、トレース対象のプロセスのプロセス ID が入ります。$2 マクロ変数 (コマンド行の 2 番目のオペランド) には、すべての関数呼び出しをトレースする関数の名前が入ります。
例 33–1 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 という名前のファイルに保存し、chmod で実行可能ファイルに変更します。このスクリプトからは、次のような結果が出力されます。
# ./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 マクロ変数 (第 15 章スクリプトの作成を参照) と、dtrace コマンドの -c オプションと-p オプションを使って、プロセスを作成し、取り込みます。さらに、DTrace を使って、これらのプロセスを計測します。たとえば、次の D スクリプトでは、特定の従属プロセスによって実行される libc の関数呼び出しの内訳がわかります。
pid$target:libc.so::entry
{
@[probefunc] = count();
}
このスクリプトを libc.d という名前のファイルに保存し、次のコマンドを実行すると、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 プロバイダと投機トレース (第 13 章投機トレースを参照) を組み合わせて、関数内のすべての命令を個別にトレースすると、この問題を解決できます。
例 33–2 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 |
- © 2010, Oracle Corporation and/or its affiliates