第81回　DTraceの使い方その1

DTraceと教科書

数回にわたってシステムやプロセスのパフォーマンスをチェックするコマンドを取り上げてきました。その中で何度かDTraceの機能を使ったコマンドや、dtrace(1)を使ってパフォーマンスをチェックする方法を紹介しました。今回からしばらくはこのDTraceを使ったパフォーマンスチェックの方法を紹介しようと思います。

DTraceが提供するカーネルやユーザランドプロセスのモニタリング機能や分析機能は多岐に渡ります。現在ではカーネルやソフトウェアを再構築する必要なく、デフォルトの状態でさまざまなモニタリングが可能になっています。

DTraceを使い出すにあたって、まず教科書的に利用できる書籍「DTrace: Dynamic Tracing in Oracle Solaris, Mac OS X and FreeBSD」を紹介しておきます。

DTrace: Dynamic Tracing in Oracle Solaris, Mac OS X and FreeBSD
Brendan Mauro、Jim Gregg(著)
ISBN-10: 0132091518、ISBN-13: 978-0132091510

「DTrace: Dynamic Tracing in Oracle Solaris, Mac OS X and FreeBSD」は2011年に出版された書籍で、DTraceの解説書籍としては古典になりつつあります。書籍の内容はすでに古く、取り上げられているFreeBSDのバージョンもFreeBSD 7および8系列と、すでにサポートの対象外となったブランチです。

さらに、書籍に掲載されているスクリプトは基本的にSolarisが対象となっているためそのままではFreeBSDでは利用できないものが多数含まれています。FreeBSDで利用するには、ヘッダファイルを読むなどしてFreeBSDで利用できるようにちょっと書き換えをおこなってあげる必要があります。

しかし、この書籍はDTraceの仕組みや機能を幅広く網羅し、さらに利用例が豊富に掲載されています。DTraceでどんなことを実施できるのか学ぶには優れた内容です。DTraceを使っていこうと考えている場合には手元においておくべき書籍だと思います。

同書の第1章に掲載されているサンプルをFreeBSDで動作するように少々変更したものを次に掲載しておきます。

どのプロセスがどのファイルをオープンしたかといったことは、時に知りたくなる情報です。どの設定ファイルの内容を読みにいったのか知りたいとか、どのファイルから影響を受けているのかとか、どのファイルにデータを書き出しているのかを知りたいといった場合です。コマンドでそれを提供しているものもありますが、DTraceを使うともっと強力に、もっと絞り込んだ内容を得ることができます。たとえば次のようにdtrace(1)コマンドをrootユーザで実行すると、どのプロセスがどのファイルをオープンしたのか、そしてそのオープンした回数を表示させることができます。

図　プロセスとプロセスがオープンしたファイルをチェック

# dtrace -n 'syscall::open:entry /execname != "dtrace"/ {
    @reads[execname, copyinstr(arg0)] = count(); }'
dtrace: description 'syscall::open:entry ' matched 2 probes
^C

  fish     /Users/daichi/Documents/fdt/20161212/commands/                    1
  ls       /Users/daichi/.termcap                                            1
  ls       /Users/daichi/.termcap.db                                         1
  ls       /usr/share/misc/termcap.db                                        1
  nvim     /Users/daichi/.config/nvim/                                       1
  nvim     /etc/nsswitch.conf                                                1
  sh       .                                                                 1
  xdtp     _xdtp_temp.2KL7RY                                                 1
  xdtp     _xdtp_temp.DJ96RY                                                 1
  xdtp     _xdtp_temp.JR77RY                                                 1
  ydwait   .                                                                 1
  ydwait   ./commands                                                        1
  fish     /Users/daichi/Documents/fdt/20161212                              2
  fish     /Users/daichi/Documents/fdt/20161212/                             2
  make     .                                                                 2
  make     /Users/daichi/Documents/fdt/20161212                              2
  make     /usr/share/mk                                                     2
  nvim     /Users/daichi/.config/nvim/dein/.dein/plugin/                     2
  nvim     /Users/daichi/.config/nvim/dein/.dein/plugin/unite/               2
  nvim     /usr/local/share/nvim/runtime/plugin/                             2
  rm       /usr/share/locale/ja_JP.UTF-8/LC_COLLATE                          2
  rm       /usr/share/locale/ja_JP.UTF-8/LC_CTYPE                            2
  rm       /usr/share/locale/ja_JP.UTF-8/LC_MESSAGES                         2
  rm       /usr/share/locale/ja_JP.UTF-8/LC_MONETARY                         2
  rm       /usr/share/locale/ja_JP.UTF-8/LC_NUMERIC                          2
  rm       /usr/share/locale/ja_JP.UTF-8/LC_TIME                             2
  sed      /usr/share/locale/ja_JP.UTF-8/LC_COLLATE                          2
  sed      /usr/share/locale/ja_JP.UTF-8/LC_CTYPE                            2
  sed      /usr/share/locale/ja_JP.UTF-8/LC_MESSAGES                         2
  sed      /usr/share/locale/ja_JP.UTF-8/LC_MONETARY                         2
  sed      /usr/share/locale/ja_JP.UTF-8/LC_NUMERIC                          2
  sed      /usr/share/locale/ja_JP.UTF-8/LC_TIME                             2
  fish     /Users/daichi/Documents/fdt/20161212/commands                     3
  ls       .                                                                 3
  nvim     /etc/pwd.db                                                       3
  vmtoolsd /etc/resolv.conf                                                  3
  xdtp     /usr/local/lib/charset.alias                                      3
  xdtp     /usr/share/i18n/csmapper/JIS/JISX0201-KANA%UCS.mps                3
  xdtp     /usr/share/i18n/csmapper/JIS/JISX0208@1990%UCS.mps                3
  xdtp     /usr/share/i18n/csmapper/JIS/JISX0212%UCS.mps                     3
  xdtp     /usr/share/i18n/csmapper/JIS/UCS%JISX0201-KANA.mps                3
  xdtp     /usr/share/i18n/csmapper/JIS/UCS%[email protected]                3
  xdtp     /usr/share/i18n/csmapper/JIS/UCS%JISX0212.mps                     3
  xdtp     /usr/share/locale/ja_JP.UTF-8/LC_COLLATE                          3
  xdtp     /usr/share/locale/ja_JP.UTF-8/LC_CTYPE                            3
  xdtp     /usr/share/locale/ja_JP.UTF-8/LC_MESSAGES                         3
  xdtp     /usr/share/locale/ja_JP.UTF-8/LC_MONETARY                         3
  xdtp     /usr/share/locale/ja_JP.UTF-8/LC_NUMERIC                          3
  xdtp     /usr/share/locale/ja_JP.UTF-8/LC_TIME                             3
  cut      /usr/share/locale/ja_JP.UTF-8/LC_COLLATE                          4
  cut      /usr/share/locale/ja_JP.UTF-8/LC_CTYPE                            4
  cut      /usr/share/locale/ja_JP.UTF-8/LC_MESSAGES                         4
  cut      /usr/share/locale/ja_JP.UTF-8/LC_MONETARY                         4
  cut      /usr/share/locale/ja_JP.UTF-8/LC_NUMERIC                          4
  cut      /usr/share/locale/ja_JP.UTF-8/LC_TIME                             4
  grep     /usr/share/locale/ja_JP.UTF-8/LC_COLLATE                          4
  grep     /usr/share/locale/ja_JP.UTF-8/LC_CTYPE                            4
  grep     /usr/share/locale/ja_JP.UTF-8/LC_MESSAGES                         4
  grep     /usr/share/locale/ja_JP.UTF-8/LC_MONETARY                         4
  grep     /usr/share/locale/ja_JP.UTF-8/LC_NUMERIC                          4
  grep     /usr/share/locale/ja_JP.UTF-8/LC_TIME                             4
  ifconfig /etc/mac.conf                                                     4
  xdtp     /usr/share/i18n/csmapper/ISO646/ISO646-US%UCS.646                 6
  xdtp     /usr/share/i18n/esdb/EUC/EUC-JP.esdb                              6
  xdtp     /usr/share/i18n/esdb/UTF/UTF-8.esdb                               6
  xdtp     /usr/share/i18n/esdb/esdb.alias.db                               12
  xdtp     /usr/share/i18n/esdb/esdb.dir.db                                 12
  sh       /usr/share/locale/ja_JP.UTF-8/LC_COLLATE                         22
  sh       /usr/share/locale/ja_JP.UTF-8/LC_CTYPE                           22
  sh       /usr/share/locale/ja_JP.UTF-8/LC_MESSAGES                        22
  sh       /usr/share/locale/ja_JP.UTF-8/LC_MONETARY                        22
  sh       /usr/share/locale/ja_JP.UTF-8/LC_NUMERIC                         22
  sh       /usr/share/locale/ja_JP.UTF-8/LC_TIME                            22
  xdtp     /usr/share/i18n/csmapper/mapper.dir                              24
  xdtp     /usr/lib/i18n                                                    42
  xdtp     /usr/share/i18n/csmapper/charset.alias                           48
  xdtp     /usr/share/i18n/csmapper/charset.alias.db                        48
#

上記コマンドを実行するとdtrace(1)はシステムをモニタリングする状態に入ります。Ctrl-Cを押すとモニタリングを終了し、集計結果を表示します。ここではdtrace(1)自身は除外していますが、パターンを変更すればより絞り込んだプロセスだけをモニタリングするといったことができます。

カーネルが実際にどういったコマンドを時系列で実行していったのかを調べることもできます。次のようにdtrace(1)コマンドを実行すると、exec(2)システムコールファミリーが呼ばれるときを捉えて表示してくれます。実際に実行されたコマンドを拾っていくことができます。

図　exec(2)系システムコールによって実行されたプログラムを時系列でチェック

# dtrace -n 'proc:::exec-success { trace(curpsinfo->pr_psargs); }'
dtrace: description 'proc:::exec-success ' matched 1 probe
CPU     ID                    FUNCTION:NAME
  0  56444                none:exec-success   nvim commands/001
  0  56444                none:exec-success   sleep 0.1
  0  56444                none:exec-success   make clean
  0  56444                none:exec-success   sh -c hostname -s
  0  56444                none:exec-success   hostname -s
  0  56444                none:exec-success   sh -c sh -c "ifconfig vmx0 | grep inet | cut -f2 -d' '"
  0  56444                none:exec-success   sh -c ifconfig vmx0 | grep inet | cut -f2 -d' '
  0  56444                none:exec-success   ifconfig vmx0
  0  56444                none:exec-success   grep inet
  0  56444                none:exec-success   cut -f2 -d
  0  56444                none:exec-success   sh -c sh -c "ifconfig vmx0 | grep inet | cut -f2 -d' ' | sed 's/\.[1-9][0-9]*$/\.1/'"
  0  56444                none:exec-success   sh -c ifconfig vmx0 | grep inet | cut -f2 -d' ' | sed 's/\.[1-9][0-9]*$/\.1/'
  0  56444                none:exec-success   ifconfig vmx0
  0  56444                none:exec-success   grep inet
  0  56444                none:exec-success   cut -f2 -d
  0  56444                none:exec-success   sed s/\.[1-9][0-9]*$/\.1/
  0  56444                none:exec-success   sh -c hostname -s
  0  56444                none:exec-success   hostname -s
  0  56444                none:exec-success   /bin/sh -e -c rm -f  typescript.html  typescript.txt  typescript.xml.~?.?.~  "#typescript.xml#"  typescript.gh
  0  56444                none:exec-success   rm -f typescript.html typescript.txt typescript.xml.~?.?.~ #typescript.xml# typescript.gh
  0  56444                none:exec-success   rm -f FREEBSD-20161212.tgz
  0  56444                none:exec-success   make
  0  56444                none:exec-success   sh -c hostname -s
  0  56444                none:exec-success   hostname -s
  0  56444                none:exec-success   sh -c sh -c "ifconfig vmx0 | grep inet | cut -f2 -d' '"
  0  56444                none:exec-success   sh -c ifconfig vmx0 | grep inet | cut -f2 -d' '
  0  56444                none:exec-success   ifconfig vmx0
  0  56444                none:exec-success   grep inet
  0  56444                none:exec-success   cut -f2 -d
  0  56444                none:exec-success   sh -c sh -c "ifconfig vmx0 | grep inet | cut -f2 -d' ' | sed 's/\.[1-9][0-9]*$/\.1/'"
  0  56444                none:exec-success   sh -c ifconfig vmx0 | grep inet | cut -f2 -d' ' | sed 's/\.[1-9][0-9]*$/\.1/'
  0  56444                none:exec-success   ifconfig vmx0
...
^C

#

dtrace(1)にオプション-nで文字列を与えていますが、これはDスクリプトまたはD言語と呼ばれるものです。プログラミング言語のD言語とは別の言語で、DTraceを使うためのスクリプトのようなものです。名前が同じなので紛らわしいところがありますが、別ものです。

DTraceの方のD言語は、作りがAWKによく似ています。AWKはパターンとアクションという2つのまとまりを繰り返し書いていく構造になっていますが、D言語もほとんど同じです。ホック対象と絞り込み条件を書き、その条件に一致したものに対するアクションを書く、これを繰り返し記述していくといった内容になっています。

D言語は量子化関数（quantize）を提供しているところも特徴的なところです。モニタリングした値を集計して量子化し、グラフにプロットするといったことがデフォルトの機能として提供されています。次の例はディスク入出力サイズをモニタリングし集計してグラフとしてプロットしたものです。

図　ディスクIOサイズを量子化してグラフにプロット

# dtrace -n 'io:::start { @bytes = quantize(args[0]->bio_bcount); }'
dtrace: description 'io:::start ' matched 1 probe
^C


           value  ------------- Distribution ------------- count
            2048 |                                         0
            4096 |@@@@@                                    29
            8192 |@@                                       9
           16384 |                                         0
           32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@        179
           65536 |                                         2
          131072 |                                         0

#

この場合ですと32キロバイトごとにディスクIOが扱われていることが多いということがわかります。このように実際にカーネルの内部ではどのサイズでデータがやりとりされているのかといったことを簡単に調べられますので、この値を参考にして無駄のないプログラムを書くことができるようになるというわけです。

この書籍が出版された当時のFreeBSDが提供していたカーネル内フックポイントは3万ほどでしたが、FreeBSD 11.0-RELEASEでは6万を超えるフックが提供されています。今後もフックポイントは増えるでしょうし、より細かくモニタリングができるようになると思います。今度しばらくはこの強力な機能をとりあげて紹介していこうと思います。DTraceを使ったことがないのであれば、ぜひこの機会に使ってもらえればと思います。