BSD界隈四方山話

第83回 DTraceの使い方 その3

この記事を読むのに必要な時間:およそ 11 分

D言語でできること サンプル続き

前回はDTraceの基本的な使い方と簡単なサンプルを紹介しました。今回はサンプルの続きを紹介しようと思います。DTraceを使ってどんなことができるのかサンプルから感じてもらえればと思います。

次のサンプルはコマンドごとにread(2)システムで実際に読み込まれたバイト数を集計して,それを2のべき数の分布グラフに表示させたものです。read(2)システムコールでは実際に読み込まれたバイト数が返値として戻ってきますので,この値を集計して分布図にまとめています(これを見るとどんな感じでコードが書かれているのか想像できるあたりがおもしろいところです)⁠

 read(2)システムコールで読み込まれたバイト数(read(2)システムコールの返値)を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がプローブで,この部分で実行するタイミングを指定していることになります。

 一定期間ごとに実行されているプロセスを調べてその回数を集計し,1秒ごとに報告

# 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)システムコールが実行されている平均時間(ナノ秒)を集計して分布グラフに出力したものです。この例だと1マイクロ秒から8マイクロ秒あたりで実行が推移していることがわかります。

 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)システムコールが終了する時の時刻の値の差分を計算して,それを集計して分布グラフに出力させています。どこの処理にどれほど時間がかかっているか調べるのはパフォーマンス分析および改善で基本的な方法の1つです。こんな感じで簡単に集計できて便利です。

次のサンプルはこれまでワンライナーで書いてきた処理をDスクリプトファイルに書いた場合のサンプルです。3行目でデフォルトのプローブファイアの出力を抑制するように設定し,4行目でスイッチレートを変更してよりクイックに表示が行われるようにしています。

リスト 新しくコマンドが実行されたらそれを逐次出力するDスクリプト

#!/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はのプローブから始まる処理は,新しく実行されたコマンド(プロセス)に関する状況を出力するものです。このDスクリプトを実行すると次のようになります。

 上記Dスクリプトの実行例

# ./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.46~48より抜粋したものです(コマンドの実行結果はFreeBSDで実行したものを掲載しています)⁠

勉強会

第60回 2月23日(木)19:00~FreeBSD勉強会

発表内容検討中。発表ネタをお持ちの方,ぜひご連絡ください。

参加申請はこちらから。

第61回 3月23日(木)19:00~FreeBSD勉強会

リキャップ・ザ・AsiaBSDCon 2017 ~日本語でふりかえるABC~

2017年3月9日(木)~12日(日)まで,東京でAsiaBSDCon 2017が開催される予定です。ぜひこのカンファレンスにご参加いただきたいわけなのですが,なかにはどうしても仕事の都合で参加できなかったとか,正直英語がよくわからなかったとか,そういった方もいらっしゃるのではないかと思います。

3月のFreeBSD勉強会では,AsiaBSDCon 2017のあとというこのタイミングを活かして,AsiaBSDCon 2017の発表内容を振り返ってみよう,というのをやってみようと思います。AsiaBSDConに参加しているにもかかわらず,これまで一度もプロシーディングを読み返したことすらないというあなた,ぜひプロシーディングを持参してご参加ください :) AsiaBSDConに参加できなかったというあなたも,この機会をお見逃しなく(できればAsiaBSDConそのものに参加した方が絶対的によいです,あしからず)⁠

FreeBSD勉強会 発表者募集

FreeBSD勉強会では発表者を募集しています。FreeBSDに関して発表を行いたい場合,@daichigotoまでメッセージをお願いします。1時間半~2時間ほどの発表資料を作成していただき発表をお願いできればと思います。

コメント

コメントの記入