StepbystepDTrace
目次
| Table of Contents |
DTrace ステップbyステップ †
１．DTrace 概要 †
１）DTraceは誰のために？
「システムは、いったい何をしているんだ???」と思った事はありませんか？DTraceは、そんなあなたのためのツールです。 アプリケーションソフトを開発している時には、デバッガを使って内部変数の動きまで調べる事ができます。しかし、ドライバなどカーネルに近い部分のソフトを開発している場合や、システム管理をしている時に、カーネルの中でどうなっているのか知りたくても調べる事ができませんでした。これを動的にトレースできるようにし、システムリソースの配分は適当か、ボトルネックはどこか、などの調査をする事も可能にしたのが、DTrace（Dynamic Trace）です。
２）DTarceとは
システム内で何が実行され、どのような値が受け渡されているか、実装されている約３万のProbe（プローブ）を使って、稼働中のシステムでリアルタイムに知ることができます。カーネルで使用されている構造体のすべての値を見ることもできるのです。Probeがオフの時には、ほとんどオーバーヘッドはありませんからご心配なく。
今まで障害解析のために一時的に使用していたデバッグ用バイナリやカーネルに入れ替えることなく、稼働中のシステムで、DTraceを使って障害解析する事が可能になります。また、mdb(Solaris Modular Debugger)に組み込んでフライトレコーダのようにシステムクラッシュ直前の状態を保存・解析する事も可能です。
ユーザプログラム・システムコール・カーネルなど、いろいろなレベルの動きをトレースできますが、セキュリティやプライバシの問題があるため、デフォルトではスーパーユーザのみがDTraceを利用できるようになっています。管理者はユーザやプロセスにDTrace実行権を与える事ができますが、最低限必要なユーザやプロセスに許可するようにしてください。
メリット
- リアルタイムに分析・診断可能
- 稼働中のシステムでそのまま使用（テストマシンを用意する必要がない）
- 低速なデバッグ用のバイナリやカーネルは、不要
特徴
- 約３万のProbe 、オフの時はオーバーヘッドなし
- コマンドでも、scriptでも実行可能
- セキュリティ面も考慮
３）Probe・Provider と それを使うコマンド
Probeは、システム内に点在しているおよそ３万もの観測ポイントです。そのProbeを提供するのが Provider（プロバイダー）で、すべてのProbeはどこかのProviderに属しています。
Providerには、dtrace、lockstat、profile、fbt、syscall、sdt、sysinfo、vminfo、pid、fasttrapがあります。
このProviderによって提供されるProbeを使うのがdtraceコマンドやmdbで、これらはコンシューマと呼ばれることもあります。次の例ではdtraceコマンドの使い方を説明していきますが、この dtrace コマンドは上記 Provider の dtrace とは異なるものです。dtrace コマンドは、例えば Provider の dtrace が提供する Probeをオンにして、そのProbeが動いた時の状態を監視するなど、Provider と Probe が提供するサービスを利用するものとなります。
４） dtraceコマンド
Probeを利用するプログラムで、D言語というC言語やAwk/Perlに似たコマンドです。Awk/Perlのように、コマンドラインでの実行も、スクリプトにして実行もできます。
※大文字DTで始まるDTraceは、Dynamic Traceのしくみすべてをまとめた総称で、小文字のdtraceはここで説明したdtraceコマンドとProviderの名前の両方に使用します。
５） DTrace 開発エピソード
Mike Shapiro, Bryan Cantrill, Adam Leventhal -- DTrace Architectsの コメントより抜粋。
「今まで、複雑かつ最適化されたシステムの動きを追うのに、大変な時間を費やして きました。DTraceのようなツールが欲しいと思って１０年近く。ようやく夢が実現 したのです。DTraceを設計し完成させるのに２年近く要しましたが、その間に DTraceはサンで必要不可欠なツールになりました。グループ外の最初のDTrace ユーザは 『the best thing since sliced bread, twist-off bottle caps, cell phones and caffeine.』 （これは、スライスしたパン、ねじって開けるビンのキャップ、携帯電話、カフェイン以来の 最高傑作だ！） と言っています。みなさんもこの感動を体験してください。」
２．dtraceの使い方（１） †
まずは、コマンドラインで使う方法を説明します。
説明を読みながら、ご自分の環境でオペレーションをお試しください。
準備）あらかじめsuperuserになっておきます。
１）BEGIN というProbeの表示
dtrace(Provider)には、dtraceコマンドが動き始めた時に必ず通る「BEGIN」というProbeが用意されています。これを表示させてみましょう。
# dtrace -n BEGIN
画面には以下のように出てきます。
dtrace: description 'BEGIN' matched 1 probe CPU ID FUNCTION:NAME 0 1 :BEGIN
これは、ProbeID 1 の「BEGIN」が動いたことを表しています。
[Ctrl]key+[C]keyを押下（以下 ^C と表記）するとdtraceコマンドが終了し コマンドラインに戻ります。
２）BEGIN、ENDという２つのProbeの表示
dtrace(Provider)には、dtraceコマンドが終了する時に必ず通る「END」という Probeも用意されています。１）で表示させた「BEGIN」と共に「END」も表示させて みましょう。
# dtrace -n BEGIN -n END
画面には以下のように出てきます。
dtrace: description 'BEGIN' matched 1 probe dtrace: description 'END' matched 1 probe CPU ID FUNCTION:NAME 0 1 :BEGIN
^C を押下すると下のように１行出力してからdtraceコマンドが終了し、コマンド ラインに戻ります。
^C 0 2 :END #
これは、１）と同じProbe「BEGIN」が動いたあと、その他のオンになっているProbeが 動くのを待っているのですが、その他のProbeをオンにしていないので何も出力され ません。その後 ^C で終了したときにProbeID 2 の「END」というProbeが動きdtrace コマンドが終了した事を表しています。
３）Probe一覧の表示
# dtrace -l
とすると膨大なProbe一覧が画面に流れていきます。終了させたい場合は ^C を押下 して終了させてください。
ID PROVIDER MODULE FUNCTION NAME 1 dtrace BEGIN 2 dtrace END 3 dtrace ERROR 4 syscall nosys entry 5 syscall nosys return 6 syscall rexit entry 7 syscall rexit return 8 syscall forkall entry 9 syscall forkall return 10 syscall read entry 11 syscall read return 12 syscall write entry 13 syscall write return 14 syscall open entry 15 syscall open return 16 syscall close entry 17 syscall close return
（このあと、ずっと続きます。）
あまりにたくさんのProbeがあるので、ワードカウンタを使って行数を調べてみると そのシステムでのProbe数がわかります。
# dtrace -l | wc -l
ここで出てくる行数は、タイトル行も含むのでProbe数より１多い数字になります。 また、Probe数はインストールしたOSやソフトウェアによって異なります。wcの 出力例は次のようになります。
29955
ここでカウントされるのは既に存在するProbeですが、DTraceでは新たなProbeを 作る事ができるので正確にはProbe数は無限なのです。
さて dtrace -l の出力結果に戻ると、「ID,PROVIDER,MODULE,FUNCTION NAME」と 並んでいます。IDは各Probe固有の番号ですが、それだけではわかりにくいので PROVIDER,MODULE,FUNCTION,NAME と 階層分けして意味のある名前が付いています。 この名前を使ってどのProbeをオンにするか指定します。
３．dtraceの使い方（２） †
次に、D言語のスクリプト（以下 Dscriptと呼びます）で使う方法を説明します。
<step by step>
説明を読みながら、ご自分の環境でオペレーションをお試しください。
準備）あらかじめsuperuserになっておきます。
１）はじめに
# date
dateコマンドを実行すると画面に結果が表示されます。
2004年05月12日 (水) 15時40分44秒 JST
１行表示されるだけですが、実際には多くのシステムコールが呼ばれています。 dateコマンドが、内部でどのようなシステムコールを実行しているかtrussコマンドで 見てみます。
# truss date
と実行すると
execve("/usr/bin/date", 0x08047DB4, 0x08047DBC) argc = 1
sysconfig(_CONFIG_PAGESIZE) = 4096
resolvepath("/usr/bin/date", "/usr/bin/date", 1023) = 13
resolvepath("/lib/ld.so.1so.1", "/lib/ld.so.1", 1023) = 12
mmap(0x00000000, 4096, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANON, -1, 0) = 0xD2FC0000
（長いので、途中省略します）
read(3, " T Z i f\0\0\0\0\0\0\0\0".., 73) = 73
close(3) = 0
ioctl(1, TCGETA, 0x08047C34) = 0
fstat64(1, 0x08047BA0) = 0
2004年05月12日 (水) 15時40分49秒 JST
write(1, " 2 0 0 4C7AF 0 5B7EE 1 2".., 37) = 37
_exit(0)
dateコマンドを実行するために実際に呼ばれている、すべてのシステムコールが 表示されます。こんなに多くのシステムコールが呼ばれている事に驚かれた方も いらっしゃるのではないでしょうか？
２）Dscript作成
では、unixコマンドやプログラムの中でread()、write()システムコールが呼ばれた 時の状況をトレースする trussrw.d というDscriptを書いてみましょう。エディタで trussrw.d というファイルに以下のように書いてセーブしてください。
syscall::read:entry, syscall::write:entry
/pid == $1/
{
printf("%s(%d, 0x%x, %4d)", probefunc, arg0, arg1, arg2);
}
syscall::read:return, syscall::write:return
/pid == $1/
{
printf("\t\t = %d\n", arg1);
}
ここで$1は、このDscript実行時に渡す引数で、実行時にはトレースしたいプロセスの IDを与えます。
３）実行のための準備
実行してみる前に、もう１つ端末エミュレータを開いて下さい。以後こちらを 「端末２」と呼びます。こちらはsuperuserでなくてもＯＫです。
$ echo $$
と実行して端末２のプロセスIDを調べます。画面にプロセスIDの数字が表示されます。
3516
このプロセスIDをtrussrw.dを実行する時の引数にして、このプロセス内で read()、write()システムコールが呼ばれるのをトレースします。
４）Dscript実行
trussrw.dを作成したsuperuserの画面（以後、「端末１」と呼びます。）に戻って trussrw.dを実行します。
# dtrace -s trussrw.d 3516
（-sは「その後に指定するscriptファイルにより実行する」というオプションで、 最後の3516というのは、３）実行のための準備 で調べた端末２のプロセスIDです。）
５）端末２でunixコマンドを実行
端末２でunixコマンド（例：ls）を実行してみます。
$ ls
ls 以外にも cd や vi などいろいろ実行してみてください。するとdtraceを実行 している端末１にはread()、write()システムコールに入った時と出た時に１行ずつ 情報が出力されます。つまり「3516」というプロセスID（端末２）で発生したプロセス の中からread()、write()システムコールを使用したすべての情報をトレースしている のです。
６）実行結果とDscriptの終了
端末１で ^C を押下するとdtraceが終了しコマンドラインに戻ります。
dtrace: script 'trussrw.d' matched 10 probes CPU ID FUNCTION:NAME 0 11 read:return = 3 0 12 write:entry write(2, 0xd2e5a53f, 2) 0 13 write:return = 2 0 10 read:entry read(0, 0x8077320, 128) ^C
CPUという欄には処理を実行しているCPU番号が、IDという欄にはProbeのID番号が FUNCTION:NAMEという欄にはProbeの名前が出力され、dscriptのprintf文で指定した ものは一番右側に出力されます。
lsを実行した時に、コマンド入力待ちだったreadから抜け、writeに入り、lsの 結果を画面に出力してwriteから出て、次のコマンド入力待ちのreadに入った 状態に戻っている事がわかります。
７）Dscriptの解説
２）で作成したscript"trussrw.d"を簡単に解説してみます。次のように各行に 行番号をつけておきます。
1 syscall::read:entry, syscall::write:entry
2 /pid == $1/
3 {
4 printf("%s(%d, 0x%x, %4d)", probefunc, arg0, arg1, arg2);
5 }
6
7 syscall::read:return, syscall::write:return
8 /pid == $1/
9 printf("\t\t = %d\n", arg1);
10 }
一見して、１〜５行目と７〜１０行目は似たような記述だとわかります。 １〜５行目で、read()、write()システムコールに入った時printfを実行し ７〜１０行目でread()、write()システムコールから出る時にprintfを実行 します。
１〜５行目を例に、もう少し説明します。
■１行目でどのProbeをオンにするかを指定しています。Probeを指定する記述は、『 provider:module:function:name 』というフォーマットになるため、１行目のカンマまでで、providerはsyscall、functionはread、nameはentryというProbe、つまりread()システムコール（syscall）を呼んだ時点（entry）の状態を調べるProbeをオンにした事になります。
■このProbeには、module名はついていないので:で区切っている２番目には何も書いてありません。このようにmodule名が付いていないProbeは多数存在します。また、『 provider:module:function:name 』の部分はすべてを書く必要はなく、限定したい部分だけを書きます。書いていない部分はすべて適用という意味になります。たとえば『 syscall:::entry 』と書くと、syscallというproviderの中でnameがentryのすべてのProbeをオンにした事になります。
■１行目のカンマ以降は、カンマ前と同様にproviderはsyscall、functionはwrite、nameはentryというProbe、つまり、write()システムコール（syscall）を呼んだ時点（entry）の状態を調べるProbeをオンにした事になります。
■２行目の$1はこのscript実行時の引数で、調べたいプロセスのIDを与えます。/pid==$1/ は条件文で、これが真であれば｛｝内（３行目〜５行目）を実行します。
■４行目printf文はｃ言語と同じように""内のformatに従って probefunc,arg0,arg1,arg2の値を出力します。ここで、arg0,arg1,arg2は１行目で指定したfunction（read）の引数を表しています。
■７〜１０行目は上と同様に見ていくとread()、write()システムコール（syscall）から抜けた時点（return）の状態を調べるProbeをセットし、pidが引数で与えられたものと一致した時に９行目のprintfを実行します。
これで、unixコマンドやプログラムの中で、read()、write()システムコールが呼ばれた時の状況をトレースする事ができるのです。このようにDscriptで「ProbeをオンにしてそProbeが動いた時の情報を出力する」というプログラムを組む事ができるのです。 };
なんとなくご理解頂けたでしょうか？
４．dtraceの使い方（３）
もう１つDscriptの例を簡単に説明します。この例は、Java Technology Conference 2004の「Software Express for Solaris」で紹介されたものですから、ご覧になった 方もいらっしゃるのではないでしょうか？
引数で指定したファイルを、誰がどのプログラムでアクセスしたのかトレースする scriptです。
<step by step>
説明を読みながら、ご自分の環境でオペレーションをお試しください。
準備）あらかじめsuperuserになっておきます。
１）Dscript作成
エディタでtrussopen.dというファイルに以下のように書いて、セーブしてください。
#!/usr/sbin/dtrace -s
#pragma D option quiet
syscall::open*:entry
/copyinstr(arg0) == $1/
{
printf("%6d/%6d/%s\n",curthread->t_procp->p_cred->cr_uid,pid,execname)
}
ここで $1はこのDscript実行時に渡す引数で、実行時にはトレースしたいファイル名を 与えます。
２）trussopen.dに実行権限を付けます。
# chmod a+rx trussopen.d
今回はDscriptファイルに実行権限を付けて実行してみます。
３）Dscript実行
# ./trussopen.d '"test.txt"'
test.txtというのは、script中の$1に渡してトレースしたいファイル名です。 $1に"test.txt"という""付きで渡すために、引数にはさらに''を付けます。 タイプミスしないようにファイル名を""で囲み、その外側を''で囲んでください。
このDscriptを実行した端末エミュレータを「端末１」と呼びます。
４）ファイルtest.txt操作
トレースできるか確認するために、もう１つ端末エミュレータを開いて下さい。 以後、こちらを「端末２」と呼びます。こちらはsuperuserでなくてもＯＫです。
端末２で viエディタ等を使ってtest.txtというファイルを作成してみてください。 これはどこのディレクトリでも構いません。
$ vi test.txt
何か書いてセーブし、catやmoreなどでファイルtest.txtにアクセスしてみて下さい。
$ cat test.txt $ more test.txt
５）実行結果とDscriptの終了
端末１で ^C を押下するとdtraceが終了しコマンドラインに戻ります。 端末１には「ユーザID/プロセスID/実行プログラム名」が出力されています。
123456/ 5540/vi 123456/ 5541/cat 123456/ 5543/more ^C
６）Dscriptの解説
１）で作成したscript"trussopen.d"を簡単に解説してみます。次のように各行に 行番号をつけておきます。
1 #!/usr/sbin/dtrace -s
2 #pragma D option quiet
3 syscall::open*:entry
4 /copyinstr(arg0) == $1/
5 {
6 printf("%6d/%6d/%s\n",curthread->t_procp->p_cred->cr_uid,pid,execname)
7 }
■１行目はshell scriptの先頭行に #!/bin/sh と書くのと同様、dtraceを -s オプションで実行することを宣言しています。この記述があると２）３）で説明したように実行権限を付けて実行する事ができます。
■２行目は実行時にprintf文などで意図的に出力するメッセージ以外は出力しないようにするオプションで、実行時に -x quiet とオプションを付けて実行するのと同等です。実行時に毎回オプションを指定するのが面倒な場合はscript内に書いてしまう事が可能です。（３．DTraceの使い方（２）ではscriptのprintf文で出力しているもの以外にCPU番号やProbeのID番号などが出力されましたが、これらの結果を出力しないようにするオプションです。）
■３行目でproviderはsyscall、functionはopen*、nameはentryというProbeをオンにしています。つまり open()システムコールが呼ばれた（entry）時に動きます。Solarisには64bit用、32bit用の複数のopen()システムコールが存在するので、すべてのopenをトレースできるようにfunction名にワイルドカードを付けて open* としています。（３．DTraceの使い方（２）で使ったscriptではread()、write()システムコールをトレースしましたが、これもFUNCTION名に*を付けてread*／write*のように書いておく事で漏れなくトレースできます。）
■４行目でopenの引数arg0が、Dscript実行時に与えられた引数"test.txt"と一致しているか判断して、一致すれば５〜７行目が実行されます。ここは単に/arg0==$1/ と書いても比較はうまく行きません。copyinstr(arg0)でarg0の値をDTrace側に持ってきて比較しています。
■このscriptを実行する時に、引数は '"ファイル名"'のようにシングルクォート'で囲んだ中にダブルクォート"で囲んだファイル名を指定しましたが、これは実際に$1に入る値がダブルクォートで囲んだファイル名でなければならないためです。
■６行目のプリント文はC言語と同様です。ユーザIDはカレントのthread（curthread）からカーネル内の構造体をたどって行ってUIDの値を参照しています。
このように、このDscriptを使うと「引数で指定したファイルに、誰がどのプログラムでアクセスしたのか」をトレースする事ができるのです。
dtraceコマンド紹介 †
１．DTrace の利点
致命的で再現不可能なバグ・一過性のバグなど今までcoreファイルやdumpファイルで 静的に解析するしか方法がなかったバグも、DTraceを使えばシステム稼働中に動的に 解析できるようになりました。
例えば、１CPUあたり100ユーザの処理ができると思っていたら60ユーザ程度までしか 処理できないとか、毎朝9:00〜10:30頃システムの動作がおかしいというような場合、 何かがシステムのパフォーマンスを阻害しているのは分かっても、その先の解析は 大変でした。しかしdtraceコマンドを使ってProbeを立てシステム内の状態を調べる 事で、何がネックでパフォーマンスが悪くなっているのかをシステムを稼働させながら 解析できるようになったのです。
何を調べたいかによっていろいろな機能を使う事ができますが、ここではdtraceコマンド の集計機能を中心に使用例を紹介します。
２．dtraceコマンドの集計関数
dtraceコマンドではオンにしたProbeが 動いた時にいろいろな値を参照したりプリント文を実行する事ができますが、その他に集計を行う関数も用意されています。
集計関数
count() ： 引数はなく、呼ばれた回数を返す
sum() ： 引数で与えられた値の合計値を返す
avg() ： 引数で与えられた値の平均値を返す
min() ： 引数で与えられた値のうち最小値を返す
max() ： 引数で与えられた値のうち最大値を返す
lquantize()： 第１引数で与えられた値を、第２,３,４引数で与えられたリニア(線形)
の単位に分けて回数を集計し、結果をグラフで出力
quantize() ： 引数で与えられた値を２の累乗の単位に分けて集計し、結果をグラフで出力
[注]count()以外の関数には引数として１度に１つの値を与えます。これらの関数を何度も呼ぶ事で複数の値を与え、終了時には何度も呼ばれて渡されたすべての値の合計値や平均値など関数の結果を得る事ができます。
次章から例を用いて集計関数の使い方を紹介していきます。
３．集計関数count()使用例
count()は、呼ばれるたびに１ずつインクリメントして呼ばれた回数を数える集計関数 です。ここでは count()を使ってwrite()システムコールの呼ばれた回数を実行プログ ラム毎に数える例を紹介します。
＜step by step＞
説明を読みながら、ご自分の環境でオペレーションをお試しください。
準備）
端末エミュレータを２つ開きます。１つは「端末１」と呼び superuserに
なってscriptファイルを作成するディレクトリに移ります。もう１つは
「端末２」と呼び、一般ユーザでそのユーザのホームディレクトリ下に
いてください。
１）端末１でdtrace実行
端末１で次のようにdtraceコマンドを実行します。
# dtrace -n 'syscall::write:entry { @counts[execname] = count(); }'
dtraceのメッセージが１行出るだけでプロンプトは戻ってきませんが、その状態の まま次に進みます。
２）端末２でunixコマンド実行
端末２で いろいろなunixコマンド（who,ls,mkdir,cd,vi,moreなど）を実行します。 以下のコマンド以外にもいろいろ実行してみてください。
$ who $ ls $ mkdir dtrace_test $ cd dtrace_test $ vi abcd.txt $ more abcd.txt
コマンドをいくつか実行した後、次に進んで下さい。
３）端末１でdtrace終了
端末１で[Ctrl]key+[C]keyを押下（以下 ^C と表記）してdtraceを終了すると、 画面には実行プログラム名とwrite()システムコールの呼ばれた回数が次のように 表示されます。
dtrace: description 'syscall::write:entry ' matched 1 probe ^C dtrace 1 more 1 who 2 csh 6 vi 25 ls 47 dtgreet 184
これはdtraceコマンドが動いていた間、つまり "１）"でdtraceを実行してから ^C で終了するまでの間に、write()システムコールに何回入ったかを実行プログラム毎に 集計した結果です。例えばwhoを実行するためにwrite()システムコールを２回呼び、 lsを実行するためにwrite()システムコールを４７回呼んだという事がわかります。
４）dtraceコマンドの解説
ここで使用したdtraceコマンドは、
dtrace -n 'syscall::write:entry { @counts[execname] = count(); }'
でした。前回のDTraceについての記事も参照して頂きながら、次の解説をお読み ください。
-n というオプションで、次に指定するProbeをオンにし、Probeが動いた時にその後に記述してある処理を行う事を表します。
syscall::write:entry で、syscallというProviderが提供するwrite()システムコールに入った時に動くProbeをオンにしています。そのProbeが動いた時に次の｛｝内を実行します。
@集計用配列[ キー ] = 集計関数( 引数 );という記述で、dtraceコマンドの集計機能を使用することができます。この例では@counts[execname] = count();と書いてあります。@countsという集計用の配列でexecnameをキーにして集計処理を行う事を意味します。集計関数count()は「呼ばれた回数を戻り値で返す関数」で、引数はありません。つまりexecname毎に呼ばれた回数を集計します。
[注]execnameとは、実行中のプロセスからexec()システムコールに渡された実行プログラム名を指す、dtraceであらかじめ用意された変数です。
従ってこのコマンドで「実行プログラム毎に、write()システムコールに入った 回数を集計する」事ができるのです。ここにプリント文は書いてありませんが、結果は dtraceコマンドであらかじめ決められた項目が、あらかじめ決められたフォーマットで 出力されます。もちろんプリント文などを使って、独自フォーマットの結果を出力する 事も可能です。
４．集計関数avg()使用例
次に avg()を使って write()システムコールにかかった平均時間を実行プログラム毎に 集計する例を説明します。
＜step by step＞
説明を読みながら、ご自分の環境でオペレーションをお試しください。
準備）
端末エミュレータを２つ開きます。１つは「端末１」と呼び、superuserに
なってscriptファイルを作成できるディレクトリに移ります。もう１つは
「端末２」と呼び、一般ユーザでそのユーザのホームディレクトリの下に
いてください。
１）端末１でdtraceコマンドのscript作成
dtraceコマンドのscriptファイルを用意します。writetime.dというファイルに 次のように書いてセーブして下さい。
syscall::write:entry
{
self->ts = timestamp;
}
syscall::write:return
/self->ts/
{
@time[execname] = avg(timestamp - self->ts);
self->ts = 0;
}
２）端末１でdtraceコマンドのscript実行
"１）"で作成したファイルを使って端末１でdtraceを実行します。
# dtrace -s writetime.d
dtraceのメッセージが１行出るだけでプロンプトは戻ってきませんが、その状態の まま次に進みます。
３）端末２でunixコマンド実行
端末２で いろいろなunixコマンド（who,ls,cd,vi,moreなど）を実行します。 以下のコマンド以外にもいろいろ実行してみてください。
$ who $ ls $ cd dtrace_test $ vi abcd.txt $ more abcd.txt
コマンドをいくつか実行した後、次に進んで下さい。
４）端末１でdtraceコマンドのscript終了
端末１のdtraceを ^C で終了すると、画面には実行プログラム名とwrite()システム コールにかかった時間の平均値（単位 ナノ秒）が次のように表示されます。
dtrace: script 'writetime.d' matched 2 probes ^C
dtgreet 47542 ls 71212 csh 84812 more 113174 vi 114150 who 132456 dtrace 155273
この結果から、例えばwhoでwrite()システムコールにかかった平均時間は132456ナノ秒、 lsでwrite()システムコールにかかた平均時間は 71212ナノ秒だとわかります。
[注]１秒＝1,000,000,000ナノ秒
[参考] 「３.集計関数count()使用例」で得た実行結果と照らし合わせてみると、
whoを実行するためにwrite()システムコールを２回呼び、その処理時間の
平均値は132456ナノ秒となります。
この実行結果は 「３.集計関数count()使用例」で得た結果とすべてが対応
するわけではありませんが、このデータ取得時には２ユーザloginしていた
だけで変化がありませんでしたから、whoコマンドの実行結果を対応させる
事ができます。
５）scriptの解説
scriptに次のように行番号を付けます。
1 syscall::write:entry
2 {
3 self->ts = timestamp;
4 }
5
6 syscall::write:return
7 /self->ts/
8 {
9 @time[execname] = avg(timestamp - self->ts);
10 self->ts = 0;
11 }
■ １行目で、syscallというProviderが提供するwrite()システムコールに入った時に動くProbeをオンにしています。このProbeが動いた時に｛｝内つまり３行目を実行します。
■ ３行目で、その時の時刻(単位はナノ秒)をself->tsというスレッドローカル変数に代入します。self->と付く変数は同一スレッド内で有効なローカル変数で、スレッドが複数存在すれば同一の名前でも別々の変数となります。
■ ６行目で、syscallというProviderが提供するwrite()システムコールから抜けた時に動くProbeをオンにし、このProbeが動いた時に７行目の条件文を実行します。
■ ７行目で、self->tsに０以外の値が入っていたら｛｝内つまり９〜１０行目を実行する事を表します。
■ ９行目で、引数で与えられた値の平均値を返す集計関数avg()を使用しています。引数として１度に与える値は１つですが、何度も呼んで複数の値を与え、与えたすべての値の平均値を得る事ができます。 現在の時刻(timestamp)と write()システムコールに入った時の時刻(self->ts)の差(timestamp - self->ts)が、write()システムコールに入ってから出るまでにかかった時間になるので、その値を集計関数avg()に渡して平均値を求め、結果をexecnameをキーにした@timeという名前の配列で集計処理を行う事になります。
■ １０行目で、self->tsを０に戻しています。
従ってこのscriptで「実行プログラム毎にwrite()システムコールにかかった時間の 平均値を出す」事ができるのです。「３．集計関数count()使用例」と同様、ここに printf文は書いてありませんが、結果はdtraceであらかじめ決められた項目が あらかじめ決められたフォーマットで出力されます。もちろんprintf文を使って 独自フォーマットの結果を出力する事も可能です。
５．集計関数quantize()使用例
次に、quantize()を使ってwrite()システムコールにかかった時間を実行プログラム毎 に集計しグラフで出力してみます。
＜step by step＞
説明を読みながら、ご自分の環境でオペレーションをお試しください。
準備）
端末エミュレータを２つ開きます。１つは「端末１」と呼び、superuserに
なってscriptファイルを作成できるディレクトリに移ります。もう１つは
「端末２」と呼び、一般ユーザでそのユーザのホームディレクトリの下に
いてください。
１）端末１で、qwritetime.dというファイルに次のように書いてセーブして下さい。
syscall::write:entry
{
self->ts = timestamp;
}
syscall::write:return
/self->ts/
{
@time[execname] = quantize(timestamp - self->ts);
self->ts = 0;
}
２）端末１でdtraceコマンドのscript実行
"１）"で作成したファイルを使って端末１でdtraceを実行します。
# dtrace -s qwritetime.d
dtraceを実行し、プロンプトが戻ってこない状態のまま 次に進みます。
３）端末２でunixコマンド実行
端末２で、いろいろなunixコマンド（who,ls,cd,vi,moreなど）を実行します。 以下のコマンド以外にもいろいろ実行してみてください。
$ who $ ls $ cd dtrace_test $ vi abcd.txt $ more abcd.txt
コマンドをいくつか実行した後、次に進んで下さい。
４）端末１でdtraceコマンドのscript終了
端末１のdtraceを ^C で終了すると、画面には実行プログラム名とwrite()システム コールにかかった時間（左の数字）と回数（右の数字）が次のように表示されます。
dtrace: script 'qwritetime.d' matched 2 probes ^C
more
value ------------- Distribution ------------- count
32768 | 0
65536 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
131072 | 0
dtrace
value ------------- Distribution ------------- count
65536 | 0
131072 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
262144 | 0
who
value ------------- Distribution ------------- count
32768 | 0
65536 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
131072 | 0
csh
value ------------- Distribution ------------- count
32768 | 0
65536 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4
131072 |@@@@@@@@ 1
262144 | 0
vi
value ------------- Distribution ------------- count
32768 | 0
65536 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 6
131072 |@@@@@@@@@@ 2
262144 | 0
ls
value ------------- Distribution ------------- count
16384 | 0
32768 |@@@@@@@@@@@@@@@@@@@@@@@@ 29
65536 |@@@@@@@@@@@@@ 16
131072 | 0
262144 |@ 2
524288 | 0
dtgreet
value ------------- Distribution ------------- count
16384 | 0
32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 88
65536 |@ 3
131072 | 0
左側valueの数値は所要時間で、２の累乗で示されています。この数値以上・次の数値 未満の所要時間で何回処理されたかを @ でグラフ化して示しています。@ の数は 右に出ているcount値（回数）を表しています。
例えば、ls実行時に write()システムコールにかかった所要時間が 32768ナノ秒以上 65536ナノ秒未満で処理された回数 ：２９回 65536ナノ秒以上 131072ナノ秒未満で処理された回数 ：１６回 262144ナノ秒以上 524288ナノ秒未満で処理された回数 ： ２回 という事がわかります。
「３．集計関数count()使用例」の結果からlsを実行するために write()システムコールを ４７回呼んだ事がわかりましたが、今回も２９+１６+２=４７回呼んだ事がわかります。
また、「４．集計関数avg()使用例」の結果からlsを実行するために write()システムコールを呼んだ処理にかかった平均所要時間は 71212ナノ秒である事がわかります。照らしあわせると所要時間のばらつきから平均値が納得のいく数値になっている事がわかります。
[注１]lsは、同じディレクトリで表示するファイル数に増減がなければwrite()システムコールを呼ぶ回数が毎回同じなので、「３．集計関数count()使用例」や「４．集計関数avg()使用例」の結果と対応させて見る事ができます。viやmoreなど入力/表示した文字数/行数によってwrite()システムコールを呼ぶ回数が変わるものは、「３．集計関数count()使用例」や「４．集計関数avg()使用例」と同様の結果が得られるとは限りません。
[注２]グラフ横軸のスケールはdtraceが判断し、縦軸は２の累乗で決まります。ただし縦軸についてはcount値が０でグラフ出力に意味のない部分はdtraceが自動的に省略し、値の存在する部分を抜き出して出力します。例えばls実行時にwrite()システムコールにかかった所要時間は、縦軸32768ナノ秒から262144ナノ秒の部分に値が存在するため、その前後１行ずつ出力して他はグラフ出力していません。
５）scriptの解説
scriptに次のように行番号を付けます。
1 syscall::write:entry
2 {
3 self->ts = timestamp;
4 }
5
6 syscall::write:return
7 /self->ts/
8 {
9 @time[execname] = quantize(timestamp - self->ts);
10 self->ts = 0;
11 }
ここで使用したscriptは「４．dtraceの平均出力を利用」で使用したscriptと ほとんど同じ事に気付かれたでしょうか？ 違うのは９行目の集計関数だけですから 他の行は、「４．dtraceの平均出力を利用 ５）scriptの解説」を参照して頂く事にして ９行目だけを解説します。
■ ９行目で、集計関数quantize()を使用しています。これは、引数で与えられた値を２の累乗で区切って回数を集計しグラフ出力する集計関数です。timestamp - self->ts で write()システムコールに入ってから出るまでの所要時間を計算し、それを集計関数quantize()に与えてexecnameをキーにした@timeという集計用の配列を使って、処理時間を２の累乗毎に区切った回数をグラフ出力する事になります。
従って、このscriptで「実行プログラム毎にwrite()システムコールにかかった時間を ２の累乗で区切って集計しグラフで出力する」事ができるのです。
６．集計関数lquantize()使用例
次に、lquantize()を使ってグラフを出力してみます。「５．集計関数quantize()使用例」 で紹介したquantize()は２の累乗で区切って集計した結果を出力しましたが、ここで 紹介するlquantize()は、リニア(線形)に増加する値で区切って集計した結果をグラフ 出力します。
前回DTraceについての記事で、trussコマンドを使ってdateコマンド実行時に多くの システムコールを呼んでいる事を確認して頂きました。今回はdateコマンド実行時に 最初に呼ばれるexec()システムコールを抜けた時点を０として、各システムコールに 入った時点までのCPU時間をグラフ出力する例を紹介します。
＜step by step＞
説明を読みながら、ご自分の環境でオペレーションをお試しください。
準備）
端末エミュレータを２つ開きます。１つは「端末１」と呼び、superuserに
なってscriptファイルを作成できるディレクトリに移ります。もう１つは
「端末２」と呼び、一般ユーザでそのユーザのホームディレクトリの下に
いてください。
１）端末１で、dateprof.dというファイルに次のように書いてセーブして下さい。
syscall::exec:return,
syscall::exece:return
/execname == "date"/
{
self->start = vtimestamp;
}
syscall:::entry
/self->start/
{
/*
* We linearly quantize on the current virtual time minus our
* process's start time. We divide by 1000 to yield microseconds
* rather than nanoseconds. The range runs from 0 to 10 milliseconds
* in steps of 100 microseconds; we expect that no date(1) process
* will take longer than 10 milliseconds to complete.
*/
@a["system calls over time"] =
lquantize((vtimestamp - self->start) / 1000, 0, 10000, 100);
}
syscall::rexit:entry
/self->start/
{
self->start = 0;
}
２）端末１でdtraceコマンドのscript実行
"１）"で作成したdtraceのscriptファイルを端末１で実行します。
# dtrace -s dateprof.d
dtraceを実行し、プロンプトが戻ってこない状態のまま次に進みます。
３）端末２でdateコマンド実行
端末２で次のようにdateコマンドを実行します。
$ date
４）端末１でdtraceコマンドのscript終了
端末１のdtraceを ^C で終了すると、画面には次のように表示されます。
dtrace: script 'dateprof.d' matched 229 probes ^C
system calls over time
value ------------- Distribution ------------- count
< 0 | 0
0 | 1
500 |@@@@@ 9
1000 |@ 3
1500 |@ 3
2000 | 0
2500 | 0
3000 |@ 2
3500 |@ 3
4000 |@@ 5
4500 |@@@@ 8
5000 |@@@@ 8
5500 |@@@@ 7
6000 |@@ 4
6500 | 0
7000 | 1
7500 |@@ 5
8000 |@@ 5
8500 |@ 2
9000 | 1
9500 | 0
これは、以下のような結果を表しています。
左の数字は「dateコマンド実行時に最初に呼ばれるexec()システムコールを抜けた 時点から他のシステムコールに入るまでのCPU時間」を表します。
右の数字は「該当行の左の数字の所要時間以上、次の行の左の数字未満のCPU時間で 入ったシステムコール数」を表します。
１行ずつ見ていくと、
< 0 という行は、exec()システムコールを出てからCPU時間0マイクロ秒未満で 入ったシステムコール数 0 （CPU時間が０以下という事はあり得ませんが。） 0 という行は、exec()システムコールを出てからCPU時間0マイクロ秒以上 500マイクロ秒未満で入ったシステムコール数 1 500 という行は、exec()システムコールを出てからCPU時間500マイクロ秒以上 1000マイクロ秒未満で入ったシステムコール数 9 1000 という行は、exec()システムコールを出てからCPU時間1000マイクロ秒以上 1500マイクロ秒未満で入ったシステムコール数 3 1500 という行は、exec()システムコールを出てからCPU時間1500マイクロ秒以上 2000マイクロ秒未満で入ったシステムコール数 3
を表し、以下同様に解釈できます。
9000 という行は、右の数字が0でない最後の行になります。これは9000マイクロ秒以上 9500マイクロ秒未満でdateコマンドの最後のシステムコール（exit() システムコール）が呼ばれ、CPU処理が終了した事を表します。
@ で示されているのは右に表示されている回数ですが、スケールは全体の回数次第で dtraceが自動的に決めて表示します。
横軸をexec()を抜けた時点を０とするCPU時間[マイクロ秒]とし、順次システムコールを 呼んだタイミングを↑でシステムコール1、2、3･･･として図にすると、下図のように なります。
［マイクロ秒］
０ 500 1000 1500 2000 9000 9500 ｜---------｜---------｜---------｜---------｜-- 〜〜 -----｜---------｜ ↑ ↑↑↑･･･↑ ↑ ↑ ↑ ↑ ↑ ↑ （途中略） ↑ システムコール1 2 3 4 ･･･10 11 12 13 14 15 16 67
この結果を見ると、dateコマンド内で呼ばれるシステムコールは多数ありますが、 dtraceコマンドが起動してから終了するまでのCPU時間の中で、どのCPU時間帯にシステム コールが多く呼ばれているかのばらつき（分布）がわかります。
５）scriptの解説
scriptに次のように行番号を付けます。
1 syscall::exec:return,
2 syscall::exece:return
3 /execname == "date"/
4 {
5 self->start = vtimestamp;
6 }
7
8 syscall:::entry
9 /self->start/
10 {
11 /*
12 * We linearly quantize on the current virtual time minus our
13 * process's start time. We divide by 1000 to yield microseconds
14 * rather than nanoseconds. The range runs from 0 to 10 milliseconds
15 * in steps of 500 microseconds; we expect that no date(1) process
16 * will take longer than 10 milliseconds to complete.
17 */
18 @a["system calls over time"] =
19 lquantize((vtimestamp - self->start) / 1000, 0, 10000, 500);
20 }
21
22 syscall::rexit:entry
23 /self->start/
24 {
25 self->start = 0;
26 }
■１〜２行目
１行目ではsyscallというProviderが提供するexec()システムコールから抜ける時に動くProbeをオンにしています。
２行目ではsyscallというProviderが提供するexeceというMODULEを指定していますが、これはexecle()システムコールおよびexecve()システムコールを指しており、これらのシステムコールから抜ける時に動くProbeをオンにしています。
コマンドが動き始めると、最初にexec()システムコール・execle()システムコール・execve()システムコールのうちどれかが呼ばれるので、１〜２行目で２つのProbeをオンにする事で必ず動きをとらえられるようにしています。
■ ３行目で、条件文を実行し真であったら{}内（4〜6行目）を実行します。execname が date、つまりdateコマンドの実行が始まった時に５行目を実行します。
■ ５行目で、self->start というスレッドローカル変数に時刻vtimestampの値を代入します。
「５．集計関数quantize()使用例 」で、write()システムコールの所要時間を集計した時には時刻timestamp という値を使用しましたが、今回はvtimestampを使っています。timestampを使うと処理にかかった実時間を求められるのに対して、vtimestampはCPU時間(DTraceの処理にかかったCPU時間を除く)を求める事ができます。
■ ８行目で、すべてのシステムコールに入った時に動くProbeをオンにしています。
■ ９行目で、self->startに０以外の値が代入されている場合、{}内（１０〜２０行目）を実行します。
■ １１行目〜１７行目は、C言語同様/* */で囲まれているコメントです。この部分のコメントには、１９行目のlquantizeの引数が何を示しているか説明されています。
■ １８行目〜１９行目で、a[]という領域にlquantize()の結果を代入しており、[]内のキーを与える部分には文字列（集計のタイトル）を与えています。[]内にキーを与えた場合、キー毎に集計されグラフ出力されますが、今回は固定文字列を与えているため結果は１つのグラフになり、タイトルとしてその固定文字列が表示されます。
集計関数lquantize()には、 第１引数 ： 集計するための値 第２引数 ： グラフの開始値 第３引数 ： グラフの終了値 第４引数 ： グラフの間隔値 のように与えます。 この例では、 lquantize((vtimestamp - self->start) / 1000, 0, 10000, 500); と書かれており、 第１引数： 現時点でのvtimestampから、５行目でself->startに代入した 時刻を引き、CPU時間を求めています。つまり何かシステムコールを 呼ぶ毎に、dateコマンド開始からのCPU時間を計算し、集計している のです。 1000で割っているのは、vtimestampはナノ秒単位で値を返し ますがマイクロ秒単位で集計したいためです。 [参考] １マイクロ秒 ＝ １,０００ナノ秒 第２引数： ０なので、グラフは０から始まります。今回の例ではCPU時間が ０マイクロ秒以下という事はあり得ませんが、第２引数で与え られた開始値よりも下の場合を集計するために、結果には "＜第２引数"という行も出力されます。 第３引数： 10000なので、グラフは10000マイクロ秒つまり10ミリ秒まで グラフを書きます。『dateコマンドの実行は10ミリ秒以下で 必ず終わるはずだから』と１５〜１６行目のコメントに書か れています。第３引数を越える場合があれば、集計結果は "＞第３引数"という行に出力されます。 [参考] １ミリ秒 ＝ １,０００マイクロ秒 第４引数： 500なので、グラフは500マイクロ秒毎に１行で表示されます。
■ ２２行目で、exit()システムコールに入った時に動くProbeをオンにしています。つまりdateコマンドを終了する時に動くProbeです。
［注］exit()システムコールに入った時には、この２２行目が動く前に８行目が動くので、集計結果のグラフにはexit()システムコールに入った時間まで出力されます。
■ ２３行目で、self->startが０以外の値であった場合、{}内（２４〜２６行目）を実行します。
■ ２５行目で、self->startに０を代入しています。つまりdateコマンド終了時にself->startを０に戻しているのです。
従って、このscriptでdateコマンドの処理が始まってから各システムコールが呼ばれる までのCPU時間をリニアな値で区切って集計し、結果のグラフを得る事ができます。
［参考］前回のDTraceについての記事で、dateコマンドを実行するにも多くのシステムコールが 呼ばれている事を知って頂くために
$ truss date
というコマンドを実行して頂きましたが、trussコマンドで表示されるシステムコール数 （最初のexec()を除く）と今回の結果で右に表示されたシステムコール数（全行の和）は ６７で一致します。これを利用すると、どのシステムコールがどのCPU時間帯に呼ばれて いるのか解析する事ができます。
６）再度、端末１でdtraceコマンドのscriptを実行
今度はdateコマンド１回だけでなく、何度も繰り返した結果を見てみましょう。
端末１でdtraceを実行します。
# dtrace -s dateprof.d
dtraceを実行し、プロンプトが戻ってこない状態のまま次に進みます。
７）端末２でdateコマンドを何度も実行
端末２で次のようにdateコマンドを永久ループで何度も実行させます。
$ sh -c 'while true; do date >/dev/null; done'
数十秒から１分程度待って、^C で終了させます。
８）端末１でdtraceコマンドのscriptを終了
端末１のdtraceを ^C で終了すると、画面には次のように表示されます。
dtrace: script 'dateprof.d' matched 229 probes ^C
system calls over time
value ------------- Distribution ------------- count
< 0 | 0
0 |@@@@ 5879
500 |@@ 3523
1000 |@ 1723
1500 | 539
2000 | 0
2500 | 815
3000 |@@ 2857
3500 |@@ 3633
4000 |@@@@ 5802
4500 |@@@@ 5207
5000 |@@@@ 5631
5500 |@@ 2989
6000 | 599
6500 |@@ 3380
7000 |@@@ 4486
7500 |@@ 3690
8000 | 236
8500 | 0
この結果を見ると、dateコマンドを１回実行した時と同じようなばらつきでcount値に 山ができている事がわかります。従って、dateコマンドを起動してから終了するまで どのCPU時間帯に多くシステムコールが呼ばれるかというばらつきは、定常的な分布で ある事がわかります。
９）システムコールの詳細調査
"８）"の結果を見るとどのシステムコールがいつ頃呼ばれているのか知りたくなります。 dtraceのscriptを１語書き換えるだけで、どのシステムコールがいつ頃呼ばれているのか 知る事ができます。
端末１で"１）"で作成したdateprof.dというscriptの集計用配列のキーを固定文字列 "system calls over time" から あらかじめ用意された変数 probefunc に変更して dateprof2.d というファイル名でセーブして下さい。
syscall::exec:return,
syscall::exece:return
/execname == "date"/
{
self->start = vtimestamp;
}
syscall:::entry
/self->start/
{
/*
* We linearly quantize on the current virtual time minus our
* process's start time. We divide by 1000 to yield microseconds
* rather than nanoseconds. The range runs from 0 to 10 milliseconds
* in steps of 100 microseconds; we expect that no date(1) process
* will take longer than 10 milliseconds to complete.
*/
@a[probefunc] =
lquantize((vtimestamp - self->start) / 1000, 0, 10000, 500);
}
syscall::rexit:entry
/self->start/
{
self->start = 0;
}
10）端末１で"９）"で作成したdtraceコマンドのscript実行
"９）"で作成したdtraceのscriptファイルを端末１で実行します。
# dtrace -s dateprof2.d
dtraceを実行し、プロンプトが戻ってこない状態のまま次に進みます。
11）端末２でdateコマンドを何度も実行
端末２で次のようにdateコマンドを永久ループで何度も実行させます。
$ sh -c 'while true; do date >/dev/null; done'
数十秒から１分程度待って、^Cで終了させます。
12）端末１でdtraceコマンドのscriptを終了
端末１のdtraceを ^C で終了すると、画面には次のように表示されます。
dtrace: script 'dateprof2.d' matched 229 probes ^C
getrlimit
value ------------- Distribution ------------- count
2000 | 0
2500 |@@@@@@@@@@@@@@@@@@@ 376
3000 |@@@@@@@@@@@@@@@@@@@@ 409
3500 | 0
getpid
value ------------- Distribution ------------- count
2000 | 0
2500 |@@@@@@@@@@@@@@@@@ 349
3000 |@@@@@@@@@@@@@@@@@@@@@@ 436
3500 | 0
setcontext
value ------------- Distribution ------------- count
2000 | 0
2500 |@@@@@@@@@@@@ 503
3000 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1067
3500 | 0
gtime
value ------------- Distribution ------------- count
5500 | 0
6000 |@@@@@@@@@@@ 217
6500 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 550
7000 | 18
7500 | 0
read
value ------------- Distribution ------------- count
6000 | 0
6500 |@@@@@@@@@@@@@@@@@@@@@@@@ 471
7000 |@@@@@@@@@@@@@@@ 303
7500 | 11
8000 | 0
ioctl
value ------------- Distribution ------------- count
6000 | 0
6500 | 3
7000 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 683
7500 |@@@@ 95
8000 | 4
8500 | 0
write
value ------------- Distribution ------------- count
6500 | 0
7000 |@@@@@@@ 155
7500 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 604
8000 |@ 26
8500 | 0
rexit
value ------------- Distribution ------------- count
6500 | 0
7000 |@@@@@ 117
7500 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 638
8000 |@ 30
8500 | 0
memcntl
value ------------- Distribution ------------- count
500 | 0
1000 |@@@@@@@@@@@@@ 786
1500 | 0
2000 | 0
2500 | 0
3000 | 0
3500 | 0
4000 | 5
4500 |@@@@@@@@@@@@ 759
5000 |@@@@@@@@@@ 647
5500 |@@ 159
6000 | 0
resolvepath
value ------------- Distribution ------------- count
< 0 | 0
0 |@@@@@@@@@@@@@ 1572
500 | 9
1000 |@@@@@@ 777
1500 | 0
2000 | 0
2500 | 0
3000 | 0
3500 |@@ 291
4000 |@@@@ 502
4500 |@@@@@@ 772
5000 |@@@@@@ 708
5500 | 82
6000 | 0
open
value ------------- Distribution ------------- count
< 0 | 0
0 |@@@@@@@@@@@@ 1507
500 | 65
1000 | 0
1500 | 0
2000 | 0
2500 | 0
3000 | 1
3500 |@@@@@@ 748
4000 |@@@@@@ 767
4500 |@@@@@ 625
5000 |@ 214
5500 | 0
6000 | 2
6500 |@@@@@ 642
7000 |@ 136
7500 | 5
8000 | 0
fstat64
value ------------- Distribution ------------- count
6000 | 0
6500 |@@@@@@@@@ 538
7000 |@@@@@@@@@@@@@@@@@@@@@@@ 1406
7500 |@@@@@@ 396
8000 | 15
8500 | 0
close
value ------------- Distribution ------------- count
500 | 0
1000 |@@@@ 489
1500 |@@@ 297
2000 | 0
2500 | 0
3000 | 0
3500 | 70
4000 |@@@@@@@ 714
4500 |@@@@@@@ 730
5000 |@@@@@ 561
5500 |@@ 280
6000 | 0
6500 |@@@ 323
7000 |@@@@ 446
7500 | 16
8000 | 0
munmap
value ------------- Distribution ------------- count
0 | 0
500 |@@@@@@ 733
1000 | 53
1500 | 0
2000 | 1 ●●●●●●●●
2500 |@@@@@@ 740
3000 | 44
3500 | 18
4000 |@@@@@@@@@ 1075
4500 |@@@@ 571
5000 |@@@@@ 689
5500 | 31
6000 |@@@@@@ 712
6500 | 44
7000 | 0
stat
value ------------- Distribution ------------- count
< 0 | 0
0 |@@@@@@@@@@@ 1523
500 | 49
1000 | 0
1500 | 0
2000 | 0
2500 | 0
3000 | 13
3500 |@@@@@ 772
4000 |@@@@@ 757
4500 |@@@@ 682
5000 |@@@@@ 759
5500 |@@@@@@ 942
6000 | 0
brk
value ------------- Distribution ------------- count
2500 | 0
3000 |@@@ 540
3500 |@@@@@@ 1030
4000 | 0
4500 | 0
5000 | 0
5500 | 0
6000 |@ 237
6500 |@@@@@@@@@@@@@@@@@ 2725
7000 |@@@@@@@@@ 1485
7500 |@ 250
8000 | 13
8500 | 0
mmap
value ------------- Distribution ------------- count
< 0 | 0
0 |@@@@ 1624
500 |@@@@@@@@@ 3070
1000 | 22
1500 | 0
2000 | 0
2500 | 0
3000 | 0
3500 |@@@@ 1648
4000 |@@@@@@@@ 2748
4500 |@@@@@@ 2140
5000 |@@@@@@ 2096
5500 | 3
6000 | 0
これは"８）"で得た結果をシステムコール毎に分けて詳細に表したものです。 ただし"８）"と同時に得た結果ではないので、dateコマンドを永久ループで実行した 実行時間に差があり、count値は同じになりません。
このようにscriptを少し変更するだけで、概要でも詳細情報でも必要なレベルの情報を 得る事ができます。
７．まとめ
すべてのプログラムに対して紹介してきたような結果が得られますから、所要時間やCPU時間が長くネックになっている処理はどれかなど稼働中のシステム上で追跡調査する事が可能です。
致命的で再現不可能なバグ・一過性のバグなど今までcoreファイルやdumpファイルで静的に解析するしか方法がなかったバグも、DTraceを使えばシステム稼働中に動的に解析できる事がおわかり頂けたでしょうか？
何かがシステムのパフォーマンスを阻害している場合もdtraceコマンドを使ってProbeを立てシステム内の状態を調べる事で、何がネックでパフォーマンスが悪くなっているのかをシステムを稼働させながら解析できるのです。
