12 ユーザー・プロセスのトレース
DTraceは、ユーザー・プロセスの動作を把握するために役立つ非常に強力なツールです。デバッグ時やパフォーマンスの問題の解析時に、または単に複雑なアプリケーションの動作を理解しようとする場合にも、DTraceは非常に有益です。この章では、ユーザー・プロセス・アクティビティのトレースに関するDTrace機能に注目し、その使用方法について説明する例をあげます。
copyinサブルーチンとcopyinstrサブルーチン
DTraceでのプロセスの扱い方は、従来のデバッガや監視ツールとは若干異なっています。そのようなツールの多くは、プロセスのスコープ内で実行されるように見えるため、プログラム変数へのポインタの間接参照をユーザーが直接行うことができます。DTraceプローブはプロセス内で、またはプロセスの一部として実行されるのではなく、Oracle Linuxカーネルで実行されます。プロセス・データにアクセスする場合、プローブはcopyinまたはcopyinstrサブルーチンを使用して、ユーザー・プロセス・データをカーネルのアドレス空間にコピーします。
たとえば、次のwrite()システム・コールを考えてみます。
ssize_t write(int fd, const void *buf, size_t nbytes);
次のDプログラムは、write()システム・コールに渡された文字列および文字列の内容を出力する際の、正しくない例です。
syscall::write:entry
{
printf("%s", stringof(arg1)); /* incorrect use of arg1 */
}このスクリプトを実行すると、DTraceで次のようなエラー・メッセージが出力されます。
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()システム・コールに渡されるすべての文字列が示されています。ただし、次のような異常な出力が得られる場合もあります。
0 37 write:entry mada&^%**&
copyinstrサブルーチンは、NULLで終了するASCII文字列のユーザー・アドレスである入力引数に対して動作しますが、write()システム・コールに渡されるバッファは、ASCII文字列ではなくバイナリ・データを、あるいは終端NULLバイトを含まないASCII文字列を参照していることがあります。コール元が意図した文字列のみを出力するには、copyinstrサブルーチンの2つのパラメータ・バージョンを使用し、そこにターゲットの文字バッファのサイズを指定します。
syscall::write:entry { printf("%s", copyinstr(arg1, arg2)); }
あるいは、次のように、アドレスとサイズをとるcopyinサブルーチンを使用できます。
syscall::write:entry
{
printf("%s", stringof(copyin(arg1, arg2)));
}
DTraceがcopyinを使用して取得したユーザー・データを正しく文字列に変換するには、stringof演算子が必要です。copyinstrサブルーチンを使用する場合は、常にstring型を返すため、stringofは必要ありません。
エラーの回避
copyinおよびcopyinstrサブルーチンは、過去にアクセスされたことのないユーザー・アドレスを読み取ることができません。したがって、そのアドレスを含むページが、過去にアクセスされてフォルト・インされたことがない場合、たとえそのアドレスが有効であってもエラーが発生する可能性があります。次に例を示します。
# dtrace -n syscall::open:entry'{ trace(copyinstr(arg0)); }'
dtrace: description 'syscall::open:entry' matched 1 probe
CPU ID FUNCTION:NAME
1 8 open:entry /dev/sr0
1 8 open:entry /var/run/utmp
1 8 open:entry /dev/sr0
dtrace: error on enabled probe ID 2 (ID 8: 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
dtrace: description 'syscall::open:return' matched 1 probe
CPU ID FUNCTION:NAME
0 9 open:return /dev/sr0
1 9 open:return /usr/lib64/gconv/gconv-modules.cache
0 9 open:return /dev/sr0
0 9 open:return public/pickup
1 9 open:return maildrop
1 9 open:return /dev/sr0
1 9 open:return /dev/sr0
1 9 open:return /var/run/utmp
...dtraceの干渉の排除
write()システム・コールのすべてのコールをトレースすると、コールするたびに、dtraceコマンドが出力表示のためにwrite()をコールするため、出力がカスケードされます。このフィードバック・ループは、必要なデータの出力をdtraceコマンドが干渉している一例です。このタイプの不要なデータがトレースされないようにするには、次の例に示すような単純な述語を使用し、それをstringof.dという名前のファイルに保存します。
syscall::write:entry
/pid != $pid/
{
printf("%s", stringof(copyin(arg1, arg2)));
}
前述の例では、$pidマクロ変数は、プローブを有効にしたプロセスのプロセスIDに展開されます。pid変数には、プローブが起動したCPU上でスレッドを実行していたプロセスのプロセスIDが格納されます。したがって、述語/pid != $pid/を使用すると、このスクリプト自体に関連したイベントをトレースしないようにできます。
syscallプロバイダの使用
syscallプロバイダを使用すると、すべてのシステム・コールの開始と終了をトレースできます。psやtopなどのコマンドの出力に示されているように、特にプロセスがカーネル内での実行やブロックに多くの時間を費やしているように見える場合は、システム・コールがプロセスの動作を理解するための有効な出発点になります。
たとえば、プロセスID 31337のプロセスが、システム時間を大量に消費している場合を考えます。この動作の原因のとして考えられるのは、このプロセスが大量のシステム・コールを実行しているのではないかということです。コマンドラインから、最も頻繁に発生しているシステム・コールを調べる単純なDプログラムを実行してみましょう。
# dtrace -n syscall:::entry'/pid == 31337/{ @syscalls[probefunc] = count(); }'
dtrace: description ’syscall:::entry’ matched 215 probes
^C
kill 1
clone 4
pipe 4
setpgid 4
rt_sigreturn 6
sendmsg 7
socket 7
access 8
getegid 8
geteuid 8
getgid 8
getuid 8
wait4 12
close 15
read 23
newstat 25
write 42
ioctl 65
rt_sigaction 168
rt_sigprocmask 198
write 1092
前述の出力結果から、最も頻繁にコールされているシステム・コールがわかります。この例では、write()システム・コールです。
次のように、syscallプロバイダを使用して、すべてのwrite()システム・コールのコール元について詳細に調べることができます。
# dtrace -n syscall::write:entry'/pid == 31337/{ @writes = 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
前述の出力によると、このプロセスは比較的少量のデータに対して多数のwrite()システム・コールを実行していることがわかります。このプロセスの場合、この不均衡がパフォーマンスの問題の原因になっていると考えられます。この例で、システム・コールの動作について調査する一般的な方法がわかりました。
ustackアクション
ノート:
削除された実行可能ファイルでのシンボル参照を実行する場合、プログラムをリンクするときに--export-dynamicオプションを指定する必要があります。このオプションにより、リンカーですべてのシンボルが動的シンボル表(実行時に動的オブジェクトから参照可能なシンボルのセット)に追加されます。gccを使用してオブジェクトをリンクする場合、正しいオプションをリンカーに渡すためにオプションを-Wl,--export-dynamicとして指定します。
共有ライブラリまたは削除されていない実行可能ファイルでシンボルを検索する場合、--export-dynamicオプションは必要ありません。
特定のプローブがアクティブ化されたときにプロセス・スレッドのスタックをトレースすると、問題の詳細な調査に役立つ場合がよくあります。ustackアクションは、ユーザー・スレッドのスタックをトレースします。たとえば、多数のファイルを開くプロセスがあり、ときどきopen()システム・コールで失敗する場合、ustackアクションを使用して失敗したopenを実行するコード・パスを発見できます。次のソース・コードを入力し、badopen.dという名前のファイルに保存します。
syscall::open:entry
/pid == $1/
{
self->path = copyinstr(arg0);
}
syscall::open:return
/self->path != NULL && errno != 0/
{
printf("open for '%s' failed", self->path);
ustack();
}
このスクリプトでは、dtraceコマンド行に最初に指定されたオペランドの値が入る$1マクロ変数の使用方法も示されています。
# dtrace -s ./badopen.d 3430
dtrace: script './badopen.d' matched 2 probes
CPU ID FUNCTION:NAME
1 489 openat:return open for '/usr/lib/foo' failed
libc.so.6`sleep+0xe0
ld-linux-x86-64.so.2`do_lookup_x+0x847
libc.so.6`0x3cb8003630
libc.so.6`0x3cb8003c48
libc.so.6`0x3cb800e2c8
libc.so.6`0x3cb8003c48
looper`0x400612
libc.so.6`getenv+0x2a
looper`0x4003c8
looper`0x4009b0
libc.so.6`0x3cb800e2c8
looper`0x4009b0
looper`doOpenLoop+0x33
looper`0x400e9c
looper`main+0x5f
looper`0x400ea9
libc.so.6`__libc_start_main+0xfd
looper`main
looper`0x4009b0
looper`__libc_csu_init
ustackアクションは、スタックのプログラム・カウンタ(PC)値を記録し、dtraceコマンドがプロセスのシンボル表を検索してPC値をシンボル名に解決します。dtraceでPC値をシンボルに解決できない場合、その値は16進の整数として出力されます。
ustackデータが出力用にフォーマットされる前にプロセスが終了または中断した場合、dtraceがスタック・トレース内のPC値をシンボル名に変換できず、16進の整数として表示する場合があります。
uregs[]配列
uregs[]配列を使用すると、個々のユーザー・レジスタにアクセスできます。表12-1を参照してください。これは、サポートされている各アーキテクチャのuregs[]配列に対する索引定数を示しています。
次の表に、サポートされている各アーキテクチャのuregs[]配列に対する索引定数をリストします。
表12-1 x86 uregs[]定数
| 定数 | レジスタ | アーキテクチャ |
|---|---|---|
|
|
プログラム・カウンタ・レジスタ |
x86、AMD64 |
|
|
スタック・ポインタ・レジスタ |
x86、AMD64 |
|
|
最初のリターン・コード |
x86、AMD64 |
|
|
2番目のリターン・コード |
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
x86、AMD64 |
|
|
|
AMD64 |
|
|
|
AMD64 |
|
|
|
AMD64 |
|
|
|
AMD64 |
|
|
|
AMD64 |
|
|
|
AMD64 |
|
|
|
AMD64 |
|
|
|
AMD64 |
|
|
|
AMD64 |
|
|
|
AMD64 |
|
|
|
AMD64 |
|
|
|
AMD64 |
|
|
|
AMD64 |
|
|
|
AMD64 |
|
|
|
AMD64 |
|
|
|
AMD64 |
|
|
|
AMD64 |
pidプロバイダの使用
pidプロバイダを使用すると、プロセス内のすべての命令をトレースできます。他のほとんどのプロバイダとは異なり、pidプローブは、Dプログラムにあるプローブ記述に基づいてオンデマンドで作成されます。そのため、pidプローブは、有効にするまでdtrace -lコマンドの出力には表示されません。
ユーザー関数境界トレース
pidプロバイダに対する最も単純な操作モードは、ユーザー空間に関数境界トレースを提供することです。次のプログラム例は、単一の関数から行われたすべての関数の開始と終了をトレースします。コマンドラインの最初のオペランドである$1マクロ変数は、トレースするプロセスのプロセスIDです。コマンドラインの2つ目のオペランドである$2マクロ変数は、すべての関数コールをトレースする関数の名前です。次のソース・コードを入力し、userfunc.dという名前のファイルに保存します。
#!/usr/sbin/dtrace -s
#pragma D option flowindent
pid$1::$2:entry
{
self->trace = 1;
}
pid$1:::entry,
pid$1:::return
/self->trace/
{
}
pid$1::$2:return
/self->trace/
{
self->trace = 0;
}
前述の例のスクリプトを入力してuserfunc.dという名前のファイルに保存し、chmodコマンドを使用してファイルを実行可能にします。このスクリプトは、主バッファの詳細を含む出力を生成します。
# ./userfunc.d 123 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に対して行われる関数コールの内訳がわかります。次のソース・コードを入力し、libc.dという名前のファイルに保存します。
pid$target:libc.so::entry
{
@[probefunc] = count();
}
dateコマンドによって行われるこのようなコールの内訳を確認するには、libc.dという名前のファイルにスクリプトを保存し、次のコマンドを実行します。
# 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プロバイダと投機トレースを組み合せて、関数内のすべての命令をトレースする方法を示しています。詳細は、「投機トレース」を参照してください。
次のソース・コードを入力し、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 123 _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