D言語でできること サンプル続き
前回はDTraceの基本的な使い方と簡単なサンプルを紹介しました。今回はサンプルの続きを紹介しようと思います。DTraceを使ってどんなことができるのかサンプルから感じてもらえればと思います。
次のサンプルはコマンドごとにread(2)システムで実際に読み込まれたバイト数を集計して、
# dtrace -n 'syscall::read:return { @[execname] = quantize(arg0); }'
dtrace: description 'syscall::read:return ' matched 2 probes
^C
make
value ------------- Distribution ------------- count
-1 | 0
0 |@@@@@@@@@@@@@@@@@@@@ 8
1 | 0
2 | 0
4 |@@@@@@@@@@ 4
8 |@@@@@@@@@@ 4
16 | 0
sleep
value ------------- Distribution ------------- count
64 | 0
128 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
256 | 0
ydwait
value ------------- Distribution ------------- count
64 | 0
128 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
256 | 0
nvim
value ------------- Distribution ------------- count
0 | 0
1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 18
2 |@@@@ 2
4 | 0
8 | 0
16 | 0
32 | 0
64 | 0
128 | 0
256 |@@ 1
512 | 0
chmod
value ------------- Distribution ------------- count
64 | 0
128 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 6
256 | 0
devd
value ------------- Distribution ------------- count
64 | 0
128 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 6
256 | 0
sshd
value ------------- Distribution ------------- count
1 | 0
2 |@@@ 1
4 | 0
8 | 0
16 | 0
32 |@@@@@@@@@@@@@@@@@@@@ 8
64 |@@@@@@@@@@@@@ 5
128 |@@@ 1
256 |@@@ 1
512 | 0
hostname
value ------------- Distribution ------------- count
64 | 0
128 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 8
256 | 0
rm
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@ 2
8 | 0
16 | 0
32 |@@@@@@@ 2
64 | 0
128 |@@@@@@@@@@@@@@@@@@@@ 6
256 |@@@@@@@ 2
512 | 0
sed
value ------------- Distribution ------------- count
-1 | 0
0 |@@@@@ 2
1 | 0
2 | 0
4 |@@@@@ 2
8 |@@@@@ 2
16 | 0
32 |@@@@@ 2
64 | 0
128 |@@@@@@@@@@@@@@@ 6
256 |@@@@@ 2
512 | 0
cut
value ------------- Distribution ------------- count
-1 | 0
0 |@@@@@ 4
1 | 0
2 | 0
4 |@@@@@ 4
8 | 0
16 | 0
32 |@@@@@ 4
64 |@@@@@ 4
128 |@@@@@@@@@@@@@@@ 12
256 |@@@@@ 4
512 | 0
ifconfig
value ------------- Distribution ------------- count
-1 | 0
0 |@@@@@@@@@@ 4
1 | 0
2 | 0
4 | 0
8 | 0
16 | 0
32 | 0
64 | 0
128 |@@@@@@@@@@@@@@@@@@@@ 8
256 | 0
512 |@@@@@@@@@@ 4
1024 | 0
grep
value ------------- Distribution ------------- count
-1 | 0
0 |@@@@@ 4
1 | 0
2 | 0
4 |@@@@@ 4
8 | 0
16 | 0
32 |@@@@@ 4
64 | 0
128 |@@@@@@@@@@@@@@@ 12
256 |@@@@@@@@@@ 8
512 | 0
sh
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@ 22
8 | 0
16 | 0
32 |@@@@@@ 22
64 |@ 2
128 |@@@@@@@@@@@@@@@@@@ 66
256 |@@@@@@ 23
512 | 0
1024 |@@@ 11
2048 | 0
xdtp
value ------------- Distribution ------------- count
-1 | 0
0 |@@@@@@@@@@ 28
1 | 0
2 | 0
4 |@ 3
8 | 0
16 | 0
32 |@ 3
64 | 0
128 |@@@ 9
256 |@@@ 7
512 |@@@ 8
1024 |@@@@@@@@@@@@ 32
2048 |@@@@@@@ 19
4096 | 0
#
上記の出力がたった1行のコマンドで出力できてしまうあたりがDTraceのすごいところです。特にアグレゲーションの機能が強力で、
次のサンプルはprofileというプローブを使って指定した値毎に新しく実行されたプロセス名とその回数を集計しているというものです。集計した結果は1秒ごとに出力させています。ここではprofile-997とtick-1sがプローブで、
# dtrace -n 'profile-997 { @[execname] = count(); } tick-1s { printa(@); trunc(@); }'
dtrace: description 'profile-997 ' matched 2 probes
CPU ID FUNCTION:NAME
0 60116 :tick-1s
intr 1
vmtoolsd 1
idle 996
0 60116 :tick-1s
intr 1
idle 997
0 60116 :tick-1s
idle 997
0 60116 :tick-1s
intr 1
nvim 1
idle 995
0 60116 :tick-1s
nvim 1
rm 1
sleep 1
grep 2
hostname 2
make 2
sed 2
ifconfig 3
cut 4
sh 20
xdtp 52
idle 907
0 60116 :tick-1s
intr 1
idle 996
0 60116 :tick-1s
intr 1
idle 996
0 60116 :tick-1s
idle 997
0 60116 :tick-1s
idle 997
0 60116 :tick-1s
idle 997
0 60116 :tick-1s
chmod 1
cut 1
intr 1
rm 1
ydwait 1
hostname 2
make 2
sed 2
grep 4
ifconfig 5
sh 23
xdtp 61
idle 893
0 60116 :tick-1s
intr 2
idle 995
^C
0 60116 :tick-1s
intr 1
idle 996
#
次のサンプルはwrite(2)システムコールが実行されている平均時間
# dtrace -n 'syscall::write:entry { self->s = timestamp; } syscall::write:return /self->s/ { @["ns"] = quantize(timestamp - self->s); self->s = 0; }'
^C
ns
value ------------- Distribution ------------- count
128 | 0
256 | 55
512 |@@ 898
1024 |@@@@@@@@@@@@ 6055
2048 |@@@@@@@ 3380
4096 |@@@@@@@@ 4103
8192 |@@@@@ 2338
16384 |@ 391
32768 |@@ 894
65536 |@@@@ 1910
131072 |@ 373
262144 | 88
524288 | 26
1048576 | 9
2097152 | 10
4194304 | 6
8388608 | 1
16777216 | 1
33554432 | 1
67108864 | 0
#
このDスクリプトではスレッドローカル変数を使ってwrite(2)システムコールの処理にかかっている時間を計測しているあたりがポイントとなります。fork(2)など特定のシステムコールを除き、
ここではwrite(2)システムコールが呼ばれたときの時刻とwrite(2)システムコールが終了する時の時刻の値の差分を計算して、
次のサンプルはこれまでワンライナーで書いてきた処理をDスクリプトファイルに書いた場合のサンプルです。3行目でデフォルトのプローブファイアの出力を抑制するように設定し、
#!/usr/sbin/dtrace -s
#pragma D option quiet
#pragma D option switchrate=10hz
dtrace:::BEGIN
{
printf("%-20s %6s %6s %6s %s\n",
"ENDTIME", "UID", "PPID", "PID", "PROCESS");
}
proc:::exec-success
{
printf("%-20Y %6d %6d %6d %s\n",
walltimestamp, uid, ppid, pid, execname);
}dtrace:::BEGINのプローブから始まる処理は出力のヘッダを出す処理になっています。proc:::exec-successはのプローブから始まる処理は、
# ./pexec.d ENDTIME UID PPID PID PROCESS 2017 Jan 5 17:44:19 501 25584 29643 sleep 2017 Jan 5 17:44:19 501 25584 29644 make 2017 Jan 5 17:44:19 501 29644 29645 sh 2017 Jan 5 17:44:19 501 29644 29645 hostname 2017 Jan 5 17:44:19 501 29644 29646 sh 2017 Jan 5 17:44:19 501 29644 29646 sh 2017 Jan 5 17:44:19 501 29646 29647 ifconfig 2017 Jan 5 17:44:19 501 29646 29648 grep 2017 Jan 5 17:44:19 501 29646 29649 cut 2017 Jan 5 17:44:19 501 29644 29650 sh 2017 Jan 5 17:44:19 501 29644 29650 sh 2017 Jan 5 17:44:19 501 29650 29651 ifconfig 2017 Jan 5 17:44:19 501 29650 29652 grep 2017 Jan 5 17:44:19 501 29650 29653 cut 2017 Jan 5 17:44:19 501 29650 29654 sed 2017 Jan 5 17:44:19 501 29644 29655 sh 2017 Jan 5 17:44:19 501 29644 29655 hostname 2017 Jan 5 17:44:19 501 29644 29656 sh 2017 Jan 5 17:44:19 501 29644 29656 rm 2017 Jan 5 17:44:19 501 29644 29657 rm 2017 Jan 5 17:44:19 501 25584 29658 make 2017 Jan 5 17:44:19 501 29658 29659 sh 2017 Jan 5 17:44:19 501 29658 29659 hostname 2017 Jan 5 17:44:19 501 29658 29660 sh 2017 Jan 5 17:44:19 501 29658 29660 sh 2017 Jan 5 17:44:19 501 29660 29661 ifconfig 2017 Jan 5 17:44:19 501 29660 29662 grep 2017 Jan 5 17:44:19 501 29660 29663 cut 2017 Jan 5 17:44:19 501 29658 29664 sh 2017 Jan 5 17:44:19 501 29658 29664 sh 2017 Jan 5 17:44:19 501 29664 29665 ifconfig 2017 Jan 5 17:44:19 501 29664 29666 grep 2017 Jan 5 17:44:19 501 29664 29667 cut 2017 Jan 5 17:44:19 501 29664 29668 sed 2017 Jan 5 17:44:19 501 29658 29669 sh 2017 Jan 5 17:44:19 501 29658 29669 hostname 2017 Jan 5 17:44:19 501 29658 29670 sh 2017 Jan 5 17:44:19 501 29658 29670 sh 2017 Jan 5 17:44:19 501 29658 29670 xdtp 2017 Jan 5 17:44:19 501 29658 29671 sh 2017 Jan 5 17:44:19 501 29658 29671 chmod 2017 Jan 5 17:44:19 501 29658 29672 sh 2017 Jan 5 17:44:19 501 29658 29672 sh 2017 Jan 5 17:44:19 501 29658 29672 xdtp 2017 Jan 5 17:44:19 501 29658 29673 sh 2017 Jan 5 17:44:19 501 29658 29673 chmod 2017 Jan 5 17:44:19 501 29658 29674 sh 2017 Jan 5 17:44:19 501 29658 29674 sh 2017 Jan 5 17:44:19 501 29658 29674 xdtp 2017 Jan 5 17:44:19 501 25584 29675 ydwait ^C #
top(1)コマンドの出力をそのまま下に追加し続けるような動作をします。ワンライナーで済む場合にはその場で書いたりエイリアスにまとめておくとかしますが、
こんな感じでなんとなくDTraceで計測できる内容がわかってきたのではないかと思います。次回からはリソースに合わせてより詳しく情報を取得する方法を紹介していきます。
※ ここに掲載したサンプルコマンドは"DTrace Dynamic Tracing In Oracle Solaris, Mac OS X & FreeBSD", by Brendan Gregg and Jim Mauro P.
勉強会
第60回 2月23日（木）19:00～FreeBSD勉強会
発表内容検討中。発表ネタをお持ちの方、
参加申請はこちらから。
第61回 3月23日（木）19:00～FreeBSD勉強会
リキャップ・ザ・AsiaBSDCon 2017 ～日本語でふりかえるABC～
2017年3月9日
3月のFreeBSD勉強会では、
FreeBSD勉強会 発表者募集
FreeBSD勉強会では発表者を募集しています。FreeBSDに関して発表を行いたい場合、