第 4 章 DTrace の使用法
この章では、DTrace を使って、よくある基本的なタスクを実行する方法を確認します。さらに、何種類かのトレースについても説明します。
パフォーマンス監視
いくつかの DTrace プロバイダは、既存のパフォーマンス監視ツールに対応するプローブを実装しています。
-
vminfo プロバイダ - vmstat(1M) ツールに対応するプローブを実装
-
sysinfo プロバイダ - mpstat(1M) ツールに対応するプローブを実装
-
io プロバイダ - iostat(1M) ツールに対応するプローブを実装
-
syscall プロバイダ - truss(1) ツールに対応するプローブを実装
DTrace 機能を使用すると、バンドルされているツールから得られるのと同じ情報を、より柔軟に抽出できます。DTrace 機能は、プローブの起動時に使用できる任意のカーネル情報を提供します。DTrace 機能を使って、プロセス ID、スレッド ID、スタックトレースなどの情報を受け取ることができます。
sysinfo プロバイダを使ってパフォーマンスの問題を検査する
sysinfo プロバイダは、sys カーネル統計情報のプローブを使用できるようにします。これらの統計情報は、mpstat などのシステム監視ユーティリティーの入力となります。sysinfo プロバイダのプローブは、kstat コマンドで表示される sys の値が増分される直前に起動します。次に、sysinfo プロバイダが提供するプローブを一覧します。
- bawrite
-
バッファーからデバイスへの非同期書き出しが行われる直前に起動するプローブ。
- bread
-
デバイスからのバッファーの物理読み取りが行われたときに起動するプローブ。bread は、デバイスがバッファーを要求したあと、処理の完了が保留される前に起動します。
- bwrite
-
バッファーからデバイスへの書き出しが行われる直前に起動するプローブ。書き出しは、同期書き出し、非同期書き出しの両方を含みます。
- cpu_ticks_idle
-
定期的なシステムクロックにより、「CPU がアイドル状態である」という判断が下されたとき起動するプローブ。このプローブは、システムクロックのコンテキストで起動します。したがって、システムクロックを実行している CPU 上で起動することになります。cpu_t の引数 (arg2) は、アイドル状態だと判断された CPU を表します。
- cpu_ticks_kernel
-
定期的なシステムクロックにより、「CPU がカーネルで実行中である」という判断が下されたとき起動するプローブ。このプローブは、システムクロックのコンテキストで起動します。したがって、システムクロックを実行している CPU 上で起動することになります。cpu_t の引数 (arg2) は、カーネルで実行中であると判断された CPU を表します。
- cpu_ticks_user
-
定期的なシステムクロックにより、「CPU がユーザーモードで実行中である」という判断が下されたとき起動するプローブ。このプローブは、システムクロックのコンテキストで起動します。したがって、システムクロックを実行している CPU 上で起動することになります。cpu_t の引数 (arg2) は、ユーザーモードで実行中であると判断された CPU を表します。
- cpu_ticks_wait
-
定期的なシステムクロックにより、「CPU 上に入出力待ちのスレッドがあるほかはアイドル状態である」という判断が下されたとき起動するプローブ。このプローブは、システムクロックのコンテキストで起動します。したがって、システムクロックを実行している CPU 上で起動することになります。cpu_t の引数 (arg2) は、入出力待ち状態だと判断された CPU を表します。
- idlethread
-
CPU がアイドルループに入ったときに起動するプローブ。
- intrblk
-
割り込みスレッドがブロックされたときに起動するプローブ。
- inv_swtch
-
実行中のスレッドが CPU の解放を強制されたとき起動するプローブ。
- lread
-
デバイスからのバッファーの論理読み取りが行われたときに起動するプローブ。
- lwrite
-
バッファーからデバイスへの論理書き込みが行われたときに起動するプローブ。
- modload
-
カーネルモジュールがロードされたときに起動するプローブ。
- modunload
-
カーネルモジュールがアンロードされたときに起動するプローブ。
- msg
-
msgsnd(2) または msgrcv(2) システムコールが発行されたあと、メッセージキュー操作が行われる前に起動するプローブ。
- mutex_adenters
-
所有されている適応型ロックの獲得が試みられたときに起動するプローブ。このプローブが起動するときは、lockstat プロバイダの adaptive-block プローブ、または adaptive-spin プローブも起動します。
- namei
-
ファイルシステム内で名前の検索が試みられたときに起動するプローブ。
- nthreads
-
スレッドが作成されたときに起動するプローブ。
- phread
-
生の入出力読み取りが行われる直前に起動するプローブ。
- phwrite
-
生の入出力書き込みが行われる直前に起動するプローブ。
- procovf
-
システムのプロセステーブルのエントリがなくなったため新しいプロセスを作成できないときに起動するプローブ。
- pswitch
-
CPU が実行スレッドを切り替えたときに起動するプローブ。
- readch
-
正常に読み取りが行われたあと、この読み取りの実行スレッドに制御が移る前に起動するプローブ。読み取りは、read(2)、readv(2)、または pread(2) システムコールによって行われます。arg0 には、正常に読み取られたバイト数が格納されます。
- rw_rdfails
-
書き込み側が読み取りロックまたは書き込みロックを保持している場合、または必要としている場合に、読み取りロックが試みられたとき起動するプローブ。このプローブが起動するときは、lockstat プロバイダの rw-block プローブも起動します。
- rw_wrfails
-
読み取り側か別の書き込み側が読み取りロックまたは書き込みロックを保持している場合に、書き込みロックが試みられたとき起動するプローブ。このプローブが起動するときは、lockstat プロバイダの rw-block プローブも起動します。
- sema
-
システムコール semop(2) が発行されたあと、セマフォー操作が行われる前に起動するプローブ。
- sysexec
-
システムコール exec(2) が発行されたときに起動するプローブ。
- sysfork
-
システムコール fork(2) が発行されたときに起動するプローブ。
- sysread
-
システムコール read、readv、または pread が発行されたときに起動するプローブ。
- sysvfork
-
システムコール vfork(2) が発行されたときに起動するプローブ。
- syswrite
-
システムコール write(2)、writev(2)、または pwrite(2) が発行されたときに起動するプローブ。
- trap
-
プロセッサトラップが発生したときに起動するプローブ。ただし、一部のプロセッサ、特に UltraSPARC 系プロセッサでは、一部の軽量トラップを処理するときにこのプローブを起動しないことがあります。
- ufsdirblk
-
UFS ファイルシステムによるディレクトリブロックの読み取りが行われたときに起動するプローブ。UFS については、ufs(7FS) のマニュアルページを参照してください。
- ufsiget
-
i ノードの取得時に起動するプローブ。UFS については、ufs(7FS) のマニュアルページを参照してください。
- ufsinopage
-
データページが関連付けられていないコア内の i ノードの再利用が可能になったあと起動するプローブ。UFS については、ufs(7FS) のマニュアルページを参照してください。
- ufsipage
-
データページが関連付けられたコア内の i ノードの再利用が可能になったあと起動するプローブ。このプローブは、関連付けられたデータページがディスクにフラッシュされたあとで起動します。UFS については、ufs(7FS) のマニュアルページを参照してください。
- wait_ticks_io
-
定期的なシステムクロックにより、「CPU 上に入出力待ちのスレッドがあるほかはアイドル状態である」という判断が下されたとき起動するプローブ。このプローブは、システムクロックのコンテキストで起動します。したがって、システムクロックを実行している CPU 上で起動することになります。cpu_t の引数 (arg2) は、入出力待ち状態だと判断された CPU を表します。wait_ticks_io と cpu_ticks_wait には、意味上の違いはありません。wait_ticks_io は、履歴上の理由で提供されているだけです。
- writech
-
正常に書き込みが行われたあと、この書き込みの実行スレッドに制御が移る前に起動するプローブ。書き込みに使用されるシステムコールは、 write、writev、pwrite のいずれかです。arg0 には、正常に書き込まれたバイト数が格納されます。
- xcalls
-
クロスコールが行われる直前に起動するプローブ。クロスコールは、一方の CPU から、別の CPU によるすばやい処理を要求するオペレーティングシステム機構です。
例 4–1 sysinfo プローブで quantize 集積関数を使用する
quantize 集積関数は、引数の二乗度数分布を示す棒グラフを表示します。次の例では、quantize 関数を使って、10 秒間にシステム上の全プロセスで実行される read 呼び出しのサイズを確認します。sysinfo プローブの引数 arg0 には、統計情報の増分の分量を指定します。ほとんどの sysinfo プローブでは、この値は 1 です。ただし、readch プローブと writech プローブは例外です。これらのプローブでは、引数 arg0 に、実際に読み取られるバイト数、または実際に書き込まれるバイト数を指定します。
# cat -n read.d
1 #!/usr/sbin/dtrace -s
2 sysinfo:::readch
3 {
4 @[execname] = quantize(arg0);
5 }
6
7 tick-10sec
8 {
9 exit(0);
10 }
# dtrace -s read.d
dtrace: script 'read.d' matched 5 probes
CPU ID FUNCTION:NAME
0 36754 :tick-10sec
bash
value ---------- Distribution ---------- count
0 | 0
1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 13
2 | 0
file
value ---------- Distribution ---------- count
-1 | 0
0 | 2
1 | 0
2 | 0
4 | 6
8 | 0
16 | 0
32 | 6
64 | 6
128 |@@ 16
256 |@@@@ 30
512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 199
1024 | 0
2048 | 0
4096 | 1
8192 | 1
16384 | 0
grep
value ---------- Distribution ---------- count
-1 | 0
0 |@@@@@@@@@@@@@@@@@@@ 99
1 | 0
2 | 0
4 | 0
8 | 0
16 | 0
32 | 0
64 | 0
128 | 1
256 |@@@@ 25
512 |@@@@ 23
1024 |@@@@ 24
2048 |@@@@ 22
4096 | 4
8192 | 3
16384 | 0
|
例 4–2 クロスコールのソースを確認する
次に、mpstat(1M) コマンドの出力例を示します。
CPU minf mjf xcal intr ithr csw icsw migr smtx srw syscl usr sys wt idl 0 2189 0 1302 14 1 215 12 54 28 0 12995 13 14 0 73 1 3385 0 1137 218 104 195 13 58 33 0 14486 19 15 0 66 2 1918 0 1039 12 1 226 15 49 22 0 13251 13 12 0 75 3 2430 0 1284 220 113 201 10 50 26 0 13926 10 15 0 75 |
xcal 欄と syscl 欄の値が異常に大きいため、システムパフォーマンスが浪費されている可能性があります。システムは比較的アイドル状態にあり、入出力の待ち時間が異常に長くなっているわけでもありません。xcal 欄の数値は sys kstat の xcalls フィールドから読み取られたものであり、秒単位で表されています。クロスコールを行う実行可能ファイルを確認するには、次のような dtrace コマンドを入力します。
# dtrace -n 'xcalls {@[execname] = count()}'
dtrace: description 'xcalls ' matched 3 probes
^C
find 2
cut 2
snmpd 2
mpstat 22
sendmail 101
grep 123
bash 175
dtrace 435
sched 784
xargs 22308
file 89889
#
|
出力結果から、大量のクロスコールが file(1) と xargs(1) のプロセスによって行われていることがわかります。これらのプロセスを確認するには、pgrep(1) コマンドと ptree(1) を使用します。
# pgrep xargs
15973
# ptree 15973
204 /usr/sbin/inetd -s
5650 in.telnetd
5653 -sh
5657 bash
15970 /bin/sh ./findtxt configuration
15971 cut -f1 -d:
15973 xargs file
16686 file /usr/bin/tbl /usr/bin/troff /usr/bin/ul /usr/bin/vgrind /usr/bin/catman
|
出力結果から、xargs コマンドと file コマンドがカスタムユーザーシェルスクリプトの一部であることがわかります。このスクリプトを検出するには、次のコマンドを実行します。
# find / -name findtxt /usrs1/james/findtxt # cat /usrs1/james/findtxt #!/bin/sh find / -type f | xargs file | grep text | cut -f1 -d: > /tmp/findtxt$$ cat /tmp/findtxt$$ | xargs grep $1 rm /tmp/findtxt$$ # |
このスクリプトは、多くのプロセスを同時に実行しています。パイプ経由で大量のプロセス間通信が行われています。パイプ数が多いと、スクリプトリソースが集中的に使用されます。このスクリプトは、システム上のすべてのテキストファイルの検出を試みたあと、各ファイルから特定のテキストを検索します。
ユーザープロセスをトレースする
この節では、ユーザープロセスアクティビティーのトレースに役立つ DTrace 機能に注目し、例を挙げながらその使用法について説明します。
サブルーチン copyin() と copyinstr() を使用する
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
|
dtrace の干渉を排除する
write システムコールの呼び出しをすべてトレースすると、結果が際限なく出力されます。write() 関数の呼び出しのたびに、dtrace コマンドは、出力表示のため 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() 関数へのシステムコールが多数存在することがわかります。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() アクション
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 プロバイダでは、プロセス内の任意の命令をトレースできます。大半のプロバイダとは異なり、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 プロバイダは、すでに実行中のプロセスに対してしか使用できません。dtrace 機能を使って重要なプロセスを作成し、計測するときには、$target マクロ変数と dtrace の -c オプションおよび -p オプションを使用できます。次の 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 |
匿名トレース
この節では、DTrace コンシューマに関連付けられていないトレースについて説明します。匿名トレースは、DTrace コンシューマプロセスを実行できない場合に使用します。匿名有効化を作成できるのは、スーパーユーザーだけです。複数の匿名有効化が同時に存在することはありません。
匿名有効化
匿名有効化を作成するには、dtrace コマンドを -A オプション付きで呼び出して、必要なプローブ、述語、アクション、およびオプションを指定します。dtrace コマンドは、dtrace(7D) ドライバの構成ファイルに、要求内容に対応した一連のドライバプロパティーを追加します。構成ファイルは通常 /kernel/drv/dtrace.conf です。これらのプロパティーは、dtrace ドライバのロード時にこのドライバによって読み取られます。このドライバは、指定されたプローブと指定されたアクションを有効にし、「匿名状態」を作成して、新しい有効化に関連付けます。通常、dtraceドライバは、dtrace プロバイダとして機能するほかのドライバとともに、必要に応じてロードされます。ブート中にトレースを行うためには、なるべく早い段階で dtrace ドライバをロードする必要があります。dtrace コマンドは、必要な dtrace プロバイダと dtrace ドライバの /etc/system (system(4) を参照) に、必要な forceload 文を追加します。
その後、システムがブートすると、dtrace ドライバから、構成ファイルが正常に処理されたことを示すメッセージが発行されます。匿名有効化には、dtrace コマンドの通常使用時に使用できるあらゆるオプションを設定できます。
匿名有効化を削除するには、プローブ記述を指定せずに dtrace -A コマンドを実行します。
匿名状態を要求する
マシンが完全に起動したら、dtrace コマンドに -a オプションを指定して、既存の匿名状態を要求できます。デフォルトでは、-a オプションは、匿名状態を要求し、既存のデータを処理したあと、実行を継続します。匿名状態を消費して終了する場合は、-e オプションを追加します。
匿名状態がカーネルから消費された場合、匿名状態を元に戻すことはできません。匿名トレース状態が存在しないのに、この状態を要求した場合、dtrace コマンドは次の例のようなメッセージを返します。
dtrace: could not enable tracing: No anonymous tracing state |
欠落やエラーが発生した場合、dtrace コマンドは、匿名状態が要求された時点で適切なメッセージを返します。欠落やエラーを知らせるメッセージは、匿名状態のときも非匿名状態のときも同じです。
匿名トレースの例
次の例では、iprb(7D) モジュール内の各プローブを DTrace で匿名有効化します。
# dtrace -A -m iprb dtrace: saved anonymous enabling in /kernel/drv/dtrace.conf dtrace: added forceload directives to /etc/system dtrace: run update_drv(1M) or reboot to enable changes # reboot |
リブート後、コンソールに、指定されたプローブを有効化していることを示す dtrace ドライバからのメッセージが出力されます。
... Copyright 1983-2003 Sun Microsystems, Inc. All rights reserved. Use is subject to license terms. NOTICE: enabling probe 0 (:iprb::) NOTICE: enabling probe 1 (dtrace:::ERROR) configuring IPv4 interfaces: iprb0. ... |
マシンのリブートが完了したら、dtrace コマンドに -a オプションを指定すると、匿名状態が消費されます。
# dtrace -a
CPU ID FUNCTION:NAME
0 22954 _init:entry
0 22955 _init:return
0 22800 iprbprobe:entry
0 22934 iprb_get_dev_type:entry
0 22935 iprb_get_dev_type:return
0 22801 iprbprobe:return
0 22802 iprbattach:entry
0 22874 iprb_getprop:entry
0 22875 iprb_getprop:return
0 22934 iprb_get_dev_type:entry
0 22935 iprb_get_dev_type:return
0 22870 iprb_self_test:entry
0 22871 iprb_self_test:return
0 22958 iprb_hard_reset:entry
0 22959 iprb_hard_reset:return
0 22862 iprb_get_eeprom_size:entry
0 22826 iprb_shiftout:entry
0 22828 iprb_raiseclock:entry
0 22829 iprb_raiseclock:return
...
|
次の例では、iprbattach() から呼び出された関数だけに注目します。
fbt::iprbattach:entry
{
self->trace = 1;
}
fbt:::
/self->trace/
{}
fbt::iprbattach:return
{
self->trace = 0;
}
次のコマンドを実行します。すると、ドライバ構成ファイルの以前の設定が消去され、新しい匿名トレース要求がインストールされます。そしてリブートします。
# dtrace -AFs iprb.d dtrace: cleaned up old anonymous enabling in /kernel/drv/dtrace.conf dtrace: cleaned up forceload directives in /etc/system dtrace: saved anonymous enabling in /kernel/drv/dtrace.conf dtrace: added forceload directives to /etc/system dtrace: run update_drv(1M) or reboot to enable changes # reboot |
リブート後、コンソールに dtrace ドライバからのメッセージが出力されます。出力される有効化の情報は、前回とは若干異なっています。
... Copyright 1983-2003 Sun Microsystems, Inc. All rights reserved. Use is subject to license terms. NOTICE: enabling probe 0 (fbt::iprbattach:entry) NOTICE: enabling probe 1 (fbt:::) NOTICE: enabling probe 2 (fbt::iprbattach:return) NOTICE: enabling probe 3 (dtrace:::ERROR) configuring IPv4 interfaces: iprb0. ... |
マシンのブートが完了したら、dtrace に -a オプションと -e オプションを指定して実行します。こうすると、匿名データを消費したあとに終了します。
# dtrace -ae
CPU FUNCTION
0 -> iprbattach
0 -> gld_mac_alloc
0 -> kmem_zalloc
0 -> kmem_cache_alloc
0 -> kmem_cache_alloc_debug
0 -> verify_and_copy_pattern
0 <- verify_and_copy_pattern
0 -> tsc_gethrtime
0 <- tsc_gethrtime
0 -> getpcstack
0 <- getpcstack
0 -> kmem_log_enter
0 <- kmem_log_enter
0 <- kmem_cache_alloc_debug
0 <- kmem_cache_alloc
0 <- kmem_zalloc
0 <- gld_mac_alloc
0 -> kmem_zalloc
0 -> kmem_alloc
0 -> vmem_alloc
0 -> highbit
0 <- highbit
0 -> lowbit
0 <- lowbit
0 -> vmem_xalloc
0 -> highbit
0 <- highbit
0 -> lowbit
0 <- lowbit
0 -> segkmem_alloc
0 -> segkmem_xalloc
0 -> vmem_alloc
0 -> highbit
0 <- highbit
0 -> lowbit
0 <- lowbit
0 -> vmem_seg_alloc
0 -> highbit
0 <- highbit
0 -> highbit
0 <- highbit
0 -> vmem_seg_create
...
|
投機トレース
この節では、DTrace の「投機トレース」について説明します。投機トレース機能では、一時的にデータをトレースし、このデータをトレースバッファーに「コミット」するか「破棄」するかを決めることができます。重要でないイベントを除去する手段としては、主に「述語」を使用します。述語は、そのプローブイベントがユーザーにとって重要かどうか、プローブの起動時にわかっている際に有用です。プローブの起動後まで、そのプローブイベントが重要かどうかわからない場合には、述語はあまり有用ではありません。
あるシステムコールが一般的なエラーコードを出力してときどき異常終了する場合、エラー条件の原因となっているコードパスを調べることをお勧めします。投機トレース機能を使用すれば、1 つ以上のプローブ位置で一時的にデータをトレースしたあと、データを主バッファーにコミットするかどうかは、別のプローブ位置で決めることができます。結果的に、重要な出力だけがトレースデータとして保持されるため、事後処理の必要がありません。
投機インタフェース
表 4–1 DTrace 投機関数|
関数名 |
引数 |
説明 |
|---|---|---|
|
speculation |
なし |
新しい投機バッファーの識別子を返す |
|
speculate |
ID |
同一節内の残りの部分を、指定された ID の投機バッファーにトレースする |
|
commit |
ID |
指定された ID の投機バッファーをコミットする |
|
discard |
ID |
指定された ID の投機バッファーを破棄する |
投機の作成
speculation() 関数は、投機バッファーを割り当て、投機識別子を返します。以後、 speculate() 関数の呼び出し時には、この投機識別子を使用します。投機識別子の値がゼロの場合、この投機識別子は常に無効です。ただし、speculate()、commit()、discard() のいずれかの関数に渡すことは可能です。speculation() の呼び出しに失敗した場合、dtrace コマンドは、次のようなメッセージを返します。
dtrace: 2 failed speculations (no speculative buffer space available) |
投機の使用
投機を使用するには、すべてのデータ記録アクションの実行前に、speculation() から返された識別子を speculate() 関数に渡す節を使用してください。speculate() と同じ節に含まれるすべてのデータ記録アクションは、投機的にトレースされます。1 つの D プローブ節内で、データ記録アクションのあとに speculate() を呼び出すと、D コンパイラから、コンパイル時エラーが返されます。1 つの節には、投機トレース要求だけ、またはそれ以外のトレース要求だけを含めることができます。同じ節にこれらの両方を含めることはできません。
集積アクション、破壊アクション、exit アクションは、投機的に処理することはできません。これらのいずれかのアクションを speculate() と同じ節に含めると、コンパイル時エラーが発生します。speculate() 関数のあとに、speculate() 関数を使用することはできません。1 つの節で使用できる投機は 1 つだけです。speculate() 関数 1 個以外に何も含まれない節では、デフォルトのアクション (有効化されたプローブ ID のみをトレースする) が投機的にトレースされます。
speculation() 関数を使用するときには、通常は、speculation() 関数の結果をスレッド固有変数に割り当てます。そのあとは、このスレッド固有変数を、ほかのプローブの述語や speculate() の引数として使用します。
例 4–5 speculation() 関数の一般的な使用例
syscall::open:entry
{
self->spec = speculation();
}
syscall:::
/self->spec/
{
speculate(self->spec);
printf("this is speculative");
}
投機のコミット
投機のコミットは、commit() 関数を使って行います。投機バッファーをコミットすると、このバッファー内のデータが主バッファーにコピーされます。指定した投機バッファーに、主バッファーには収まり切らない量のデータが含まれている場合、データはコピーされず、バッファーの欠落カウントの値が大きくなります。バッファーを複数の CPU 上で投機的にトレースした場合、コミット操作を実行した CPU 上の投機データはすぐにコピーされますが、その他の CPU 上の投機データは、commit() の実行後にコピーされます。
コミットが実行されている間は、その投機バッファーを後続の speculation() 呼び出しで使用できません。各 CPU の投機バッファーが対応する CPU の主バッファーに完全にコピーされるまで待つ必要があります。コミット中のバッファーに speculate() 関数呼び出しの結果を書き込もうとすると、データは破棄されます。このとき、エラーは生成されません。その後の commit() や discard() の呼び出しも、エラーを返さずに失敗します。commit() 関数が含まれる節に、データ記録アクションを含めることはできません。しかし、同じ節に複数の commit() 呼び出しを含めて、複数のバッファーを同時にコミットすることは可能です。
投機の破棄
投機を破棄するには、discard() 関数を使用します。discard() 関数を呼び出している CPU 上でのみ投機がアクティブにされている場合は、そのバッファーを、後続の speculation() 関数呼び出しですぐに使用できます。複数の CPU 上で投機がアクティブにされている場合、破棄されたバッファーは、discard() の呼び出し後に、後続の speculation() 関数呼び出しで使用できるようになります。speculation() 関数を呼び出したときに、使用可能な投機バッファーが存在しない場合は、次のような dtrace メッセージが表示されます。
dtrace: 905 failed speculations (available buffer(s) still busy) |
投機の例
投機は、特定のコードパスを明らかにするために使用できます。open() が異常終了したときは、open(2) システムコールのコードパスをすべて表示できます。次の例を参照してください。
例 4–6 specopen.d: 異常終了した open() のコードフロー
#!/usr/sbin/dtrace -Fs
syscall::open:entry,
syscall::open64:entry
{
/*
* The call to speculation() creates a new speculation. If this fails,
* dtrace(1M) will generate an error message indicating the reason for
* the failed speculation(), but subsequent speculative tracing will be
* silently discarded.
*/
self->spec = speculation();
speculate(self->spec);
/*
* Because this printf() follows the speculate(), it is being
* speculatively traced; it will only appear in the data buffer if the
* speculation is subsequently commited.
*/
printf("%s", stringof(copyinstr(arg0)));
}
fbt:::
/self->spec/
{
/*
* A speculate() with no other actions speculates the default action:
* tracing the EPID.
*/
speculate(self->spec);
}
syscall::open:return,
syscall::open64:return
/self->spec/
{
/*
* To balance the output with the -F option, we want to be sure that
* every entry has a matching return. Because we speculated the
* open entry above, we want to also speculate the open return.
* This is also a convenient time to trace the errno value.
*/
speculate(self->spec);
trace(errno);
}
syscall::open:return,
syscall::open64:return
/self->spec && errno != 0/
{
/*
* If errno is non-zero, we want to commit the speculation.
*/
commit(self->spec);
self->spec = 0;
}
syscall::open:return,
syscall::open64:return
/self->spec && errno == 0/
{
/*
* If errno is not set, we discard the speculation.
*/
discard(self->spec);
self->spec = 0;
}
このスクリプトを実行すると、次の例のような結果が出力されます。
# ./specopen.d dtrace: script './specopen.d' matched 24282 probes CPU FUNCTION 1 => open /var/ld/ld.config 1 -> open 1 -> copen 1 -> falloc 1 -> ufalloc 1 -> fd_find 1 -> mutex_owned 1 <- mutex_owned 1 <- fd_find 1 -> fd_reserve 1 -> mutex_owned 1 <- mutex_owned 1 -> mutex_owned 1 <- mutex_owned 1 <- fd_reserve 1 <- ufalloc 1 -> kmem_cache_alloc 1 -> kmem_cache_alloc_debug 1 -> verify_and_copy_pattern 1 <- verify_and_copy_pattern 1 -> file_cache_constructor 1 -> mutex_init 1 <- mutex_init 1 <- file_cache_constructor 1 -> tsc_gethrtime 1 <- tsc_gethrtime 1 -> getpcstack 1 <- getpcstack 1 -> kmem_log_enter 1 <- kmem_log_enter 1 <- kmem_cache_alloc_debug 1 <- kmem_cache_alloc 1 -> crhold 1 <- crhold 1 <- falloc 1 -> vn_openat 1 -> lookupnameat 1 -> copyinstr 1 <- copyinstr 1 -> lookuppnat 1 -> lookuppnvp 1 -> pn_fixslash 1 <- pn_fixslash 1 -> pn_getcomponent 1 <- pn_getcomponent 1 -> ufs_lookup 1 -> dnlc_lookup 1 -> bcmp 1 <- bcmp 1 <- dnlc_lookup 1 -> ufs_iaccess 1 -> crgetuid 1 <- crgetuid 1 -> groupmember 1 -> supgroupmember 1 <- supgroupmember 1 <- groupmember 1 <- ufs_iaccess 1 <- ufs_lookup 1 -> vn_rele 1 <- vn_rele 1 -> pn_getcomponent 1 <- pn_getcomponent 1 -> ufs_lookup 1 -> dnlc_lookup 1 -> bcmp 1 <- bcmp 1 <- dnlc_lookup 1 -> ufs_iaccess 1 -> crgetuid 1 <- crgetuid 1 <- ufs_iaccess 1 <- ufs_lookup 1 -> vn_rele 1 <- vn_rele 1 -> pn_getcomponent 1 <- pn_getcomponent 1 -> ufs_lookup 1 -> dnlc_lookup 1 -> bcmp 1 <- bcmp 1 <- dnlc_lookup 1 -> ufs_iaccess 1 -> crgetuid 1 <- crgetuid 1 <- ufs_iaccess 1 -> vn_rele 1 <- vn_rele 1 <- ufs_lookup 1 -> vn_rele 1 <- vn_rele 1 <- lookuppnvp 1 <- lookuppnat 1 <- lookupnameat 1 <- vn_openat 1 -> setf 1 -> fd_reserve 1 -> mutex_owned 1 <- mutex_owned 1 -> mutex_owned 1 <- mutex_owned 1 <- fd_reserve 1 -> cv_broadcast 1 <- cv_broadcast 1 <- setf 1 -> unfalloc 1 -> mutex_owned 1 <- mutex_owned 1 -> crfree 1 <- crfree 1 -> kmem_cache_free 1 -> kmem_cache_free_debug 1 -> kmem_log_enter 1 <- kmem_log_enter 1 -> tsc_gethrtime 1 <- tsc_gethrtime 1 -> getpcstack 1 <- getpcstack 1 -> kmem_log_enter 1 <- kmem_log_enter 1 -> file_cache_destructor 1 -> mutex_destroy 1 <- mutex_destroy 1 <- file_cache_destructor 1 -> copy_pattern 1 <- copy_pattern 1 <- kmem_cache_free_debug 1 <- kmem_cache_free 1 <- unfalloc 1 -> set_errno 1 <- set_errno 1 <- copen 1 <- open 1 <= open 2 |
- © 2010, Oracle Corporation and/or its affiliates