killproc の dtrace が殺されてしまう2017年10月21日 12時02分49秒

OOM killer が呼ばれるのを、dtrace で観察しようと思った。OOM は「Out Of Memory」の略。

プロセスが選ばれてから、最後に解放されるまでの順序を探りたい。

$ dtrace -n 'fbt::killproc:entry{stack()}'
これで、まずはプロセスが落されるのを見付けれられると思ったが、そんなに簡単では無かったようだ。

pagedaemon が OOM Kill をやるのだが、メモリが枯渇している状況なので、dtrace が反応しない。dtrace 自体もスワップアウトされていたり、ページアウトされていたりする。また、シグナルの伝達も遅いので、kill シグナルが送られても、なかなかメモリが解放されずに、pagedamon が他のプロセスも殺し始めて、dtrace も落される。

vm_pageout_scan に、関数の呼び出しと終了以外の dtrace の観察点が仕掛けられているのを見付けた。

SDT_PROVIDER_DEFINE(vm);
SDT_PROBE_DEFINE(vm, , , vm__lowmem_scan);
...
                SDT_PROBE0(vm, , , vm__lowmem_scan);
dtrace でどのように呼び出せば良いかを調べる。
$ dtrace -l | grep lowmem_scan
39458         vm            kernel                              none vm-lowmem_scan
$ dtrace -n 'vm:::vm-lowmem_scan{stack()}'
          CPU     ID                    FUNCTION:NAME
  0  39458              none:vm-lowmem_scan
              kernel`0xc0b8d220

  0  39458              none:vm-lowmem_scan
              kernel`0xc0b8d220
カーネルから直接呼ばれているみたいだ。これは、11-STABLE の結果。11.2-RELEASE が前回のリリースだ。

dtrace で vm_thread_new の呼ばれる場所を探る2017年10月08日 11時02分38秒

11.1-RELEASE 後の 11-stable のコード。
$ dtrace -n 'fbt::vm_thread_new:entry{stack()}'
  0  55259              vm_thread_new:entry 
              kernel`thread_alloc+0x28
              kernel`sys_thr_new+0x67
              kernel`syscall+0xa4b
              kernel`0xc10a18fe

thread_alloc を見ると、thread_zone からメモリを割り当てているようだ。


struct thread*
thread_alloc(int pages)
{
...
    td = (struct thread *)uma_zalloc(thread_zone, M_WAITOK);

dtrace で特定の関数が呼ばれた時のコールスタックを取得2017年10月04日 21時04分47秒

スワップの実装に大きな変更があったのと、元からの興味により sys/vm/swappager.c を覗いている。

swp_pager_meta_build がいつ呼ばれるか興味があったので、久しぶりに dtrace を使ってみることにした。stack と言う関数がある。

# dtrace -n 'fbt::swp_pager_meta_build:entry{ stack() }'
dtrace: description 'fbt::swp_pager_meta_build:entry' matched 1 probe
dtrace: buffer size lowered to 6m


  0  20744       swp_pager_meta_build:entry
              kernel`swap_pager_putpages+0x266
              kernel`vm_pageout_cluster+0x4e4
              kernel`vm_pageout_laundry_worker+0x9c0
              kernel`fork_exit+0x6a
              kernel`0xc10a1b20

カーネル内では関数ポインタを設定して、あちこちに飛ぶことも多いので一部のコールスタックは、見た目程明らかではない。この出力は、11-STABLE で、11.1-RELEASE とは既にかなり異なっている。

しかし、若干これらの関数を覗いてみたところ、一部が抜けているように見える。これから、動作を探りながら dtrace の実験もしてみたい。

dtrace で pid と execname を表示2017年09月16日 13時48分36秒

dtrace で pid と execname は特殊な変数。pid はプロセス番号を保持し、execname はプログラムの名前を保持する。

open システムコールを呼び出す pid とプログラムを表示する。

$ dtrace -n 'syscall::open:entry{printf("%d %s", pid, execname)}'
dtrace: description 'syscall::open:entry' matched 1 probe
CPU     ID                    FUNCTION:NAME
  0  39684                       open:entry 13981 dtrace
  0  39684                       open:entry 13741 make
  1  39684                       open:entry 13741 make
最初に open を呼んだのは dtrace だった。

dtrace を一般ユーザで使う2015年10月15日 11時57分23秒

久しぶりに dtrace に触ってみた。以前は root で試運転してみたが、やはり root での作業は好ましくない。しかし一般ユーザではそのままでは使えない。

何はともあれまずは dtrace を読み込む。

$ kldload dtraceall
これで root が使えるようになったが、まだ一般ユーザは使えない。
% dtrace -l
dtrace: failed to initialize dtrace: DTrace requires additional privileges

一度だけなら、chmod で誰でも読み書きできる権限にする。

$ chmod go+rw /dev/dtrace/*
これで、一般ユーザでも使える。
% dtrace -l | head
   ID   PROVIDER            MODULE                          FUNCTION NAME
    1     dtrace                                                     BEGIN
    2     dtrace                                                     END
    3     dtrace                                                     ERROR
    4        fbt            kernel                camstatusentrycomp entry
    5        fbt            kernel                camstatusentrycomp return
    6        fbt            kernel            cam_compat_handle_0x17 entry
    7        fbt            kernel            cam_compat_handle_0x17 return
    8        fbt            kernel            cam_compat_handle_0x18 entry
    9        fbt            kernel            cam_compat_handle_0x18 return

dtrace の十例2009年11月21日 09時27分08秒

Top Ten DTrace (D) Scriptsにて、十個の dtrace スクリプトが公開されている。

出力例と共に出ているので、一見の価値あり。

Dtrace をかじってみて2009年04月06日 16時34分05秒

DTrace を Sun にあるサイトを中心に、試行錯誤したが思ったよりも敷居が高い。要点をまとめようと思ったが、予想していたよりも手間が掛かるのと、時間が取れなくて進んでいない。

しかし、真剣に使い始めようとしたら三つの問題に当たった。一つ目は、文法や内部関数に慣れないとなかなか使いこなせないこと。どの様な言語でもそれは当てはまるが、dtrace はその知識の蓄積が必要になる。gdb 等では、break、step。next、continue 等の三つ、四つコマンドがあれば随分と操作できるのと比べると、多きな差がある。

二つ目は、検査点がまだまだ少ないこと。FreeBSD ではまだまだ発展途上であり、カーネルにはそれなりの数の検査点が埋め込まれているが、ユーザランドから使えるのは少ない。その、カーネルに埋め込まれている検査点も偏りがあり、場所によってはほとんどないところもある。

三つ目は、プログラムがカーネルを呼び出した先の追跡が難しいこと。プロセス自体の呼び出し順を調べるのは比較的容易い。しかし、カーネルに動作が渡された後の追跡が至極難しい。例えば、read(2) された後の低次元の動作はカーネル内で行なわれる。そのため、プログラム名ではその動作が追えなくなってしまう。

DTrace を最初に試した時は柔軟性に惹かれたが、使いこなすにはそれなりの時間が必要そうだ。一朝一夕で出来るものでは無さそうだ。今後も時間の余裕がある時に、もっと取り上げていきたい。

D スクリプト言語の構文2009年03月14日 00時33分56秒

dtrace には専用の言語、D スクリプト言語がある。検査点の名前を表示するだけでなく何らかの処理を行ないたい場合は、この言語で書かれたファイルを用いる。プログラム言語としては珍しく awk 型の、パターン・アクションの構文を持つ。

D Program Structure に説明がある。以下に要点をまとめた。

D スクリプト言語は以下の形を取る。


検査点 [, 検査点]
/ 条件 /
{
    動作;
}

カンマで区切ることにより複数の検査点を羅列できる。

また、検査点にはシェルと同じメタ文字が使える。

*
空文字を含めて、全ての文字列に適合する。
?
任意の一文字に適合する。
[ ... ]
括弧の中に羅列された文字列の一つに適合する。二つの文字をハイホン「-」で繋ぐと、その範囲の文字が適合する。最初の文字がエクスクラメーションマーク「!」の場合は、羅列されていない文字に適合するようになる。
\
次に続く文字の特殊効果を無効にする。エスケープ文字。

条件はスラッシュ「/」に挟んで記述する。これらは検査点に処理が移って来た時に、真に評価された時に動作部分の実行される。この条件は省略可能である。D スクリプト言語では、0 が偽に、0 以外が真と評価される。

動作を括弧「{}」内に記述する。動作にはセミコロン「;」で区切られた複数の動作を並べることが出来る。空の動作を用いて、検査点を兎得りすぎたことを調べることも出来る。 -C オプションを用いることで、D スクリプト言語でも、C 言語の cpp プリプロセッサを呼ぶことが出来る。

dtrace 実行環境は実行時のエラー処理を行なうので、ゼロ除算や不正なメモリへのアクセスが起こると報告される。その為、dtrace がカーネルやプロセスを破壊するようなことは起こらない。

DTrace では trace/printf/printa にて出力2009年03月04日 00時56分10秒

D スクリプト言語には三つの出力関数が用意されている。trace 関数で書式を指定しないで、printf 関数で書式を指定して、データを出力できる。printa 関数は連想配列を出力するのに使う。

trace 関数は、dtrace の D スクリプト言語で結果を出力するときに使う一番簡単な関数。出力の形式は、データ型と内容によって決定される。1、2、4、8 バイトであれば数字として出力。もしそれ以外のバイト数であり、表示可能な文字であった場合は、ASCII 文字列として表示される。それ以外であれば 16 進数の羅列として表示される。

printf 関数は、C 言語のような書式を指定して、データを出力できる。printf は D スクリプト言語に組み込まれた関数であり、C 言語には無い機能を提供する。以下に幾つかの特徴的な違いを並べる。

  1. D スクリプト言語コンパイラは printf の書式とデータ型を比べて、問題があると警告する。最近の C 言語のコンパイラは、同じことをする物が多いが、これは必須ではない。
  2. C 言語では、データの大きさを示すために、l や h 等を使う。C 言語では、数値であっても short と long でバイト数が違うのを関数に教えなければならない。しかし、D スクリプト言語ではコンパイラがこれを正しく扱う為、むしろこれらの利用は非推奨になっている。
  3. %a によるポインタの出力にはシンボルとオフセットが表示されたり、%Y にて、ctime 形式の日付が出力できたりとデバッグに便利な書式が追加されている。

printa 関数は Aggregation 型のデータを表示するのに使われる。Aggregation 型はいわゆる連想配列だ。Aggregation/連想配列は統計をとる時などに有用だ。

Output Formatting にて、更に細かい解説がされている。

dtrace の stack() でスタックトレースを見る2009年02月28日 00時45分21秒

コードを追っていると目的の動作が何処で起きるのかは比較的わかりやすい。目的の関数はエラー出力や動作から簡単に掴める。しかし、その呼び出し条件を探るとなると一気に難しくなる。

Java 等では、printStackTrace() などの関数があったり、スクリプト言語でも、スタックトレースを出してくれる言語もある。しかし、C 言語となると一筋縄ではいかない。確かにデバッガを使えば判る時もあるが、プログラムの実行が大きく中断されるので、タイマーなどの動作が変わってしまう事がある。

dtrace が提供する言語、D スクリプト言語には stack 関数が用意されている。


void stack(int nframes)
void stack(void)

例として、swap-in をあげてみよう。名前の通り、関数を見つける事自体は簡単だ。しかし、どのような時に呼ばれるのかを、コードを査読するだけで掴むのは大変だ。そこで、dtrace を使う。


$ dtrace -n 'fbt::swap_pager_getpages:entry{stack()}'
dtrace: description 'fbt::swap_pager_getpages:entry' matched 1 probe

検査点に入ったときにスタックトレースを出力する。

業とスワップを起こす。そのために幾つかの方法を試してみた。


$ dd if=/dev/zero of=/mnt/tmpfs/zero bs=10M count=120
$ cat /mnt/tmpfs/zero > /dev/null
$ rm /mnt/tmpfs/zero
$ tar xvf src.tbz2 -C /mnt/tmpfs
$ cd /mnt/tmpfs/src
$ find . -type d | sed 's#^#../copy/#' | xargs mkdir -p
$ sh -c 'for f in `find . -type f`; do cp $f ../copy/$f; done'

上のコマンドを行なっている時に、出てきた出力は以下の様な結果だった。実際には、swap_pager_getpages が呼ばれる度に出力されるので、実際にはもっと大量の出力が出る。


  1  14739        swap_pager_getpages:entry 
              kernel`vm_thread_swapin+0xcc
              kernel`faultin+0xbf
              kernel`scheduler+0x412
              kernel`mi_startup+0x96
              kernel`0xc045e865

  1  14739        swap_pager_getpages:entry 
              kernel`vm_fault+0x1030
              kernel`trap_pfault+0x15b
              kernel`trap+0x27a
              kernel`0xc0a9e37b

  1  14739        swap_pager_getpages:entry
              kernel`mdstart_swap+0x3e7
              kernel`md_kthread+0x21c
              kernel`fork_exit+0x99
              kernel`0xc0a9e420

  1  14739        swap_pager_getpages:entry 
              kernel`vm_fault+0x1030
              kernel`trap_pfault+0x15b
              kernel`trap+0x417
              kernel`0xc0a9e37b
              kernel`kern_lstat+0x4f
              kernel`lstat+0x2f
              kernel`syscall+0x366
              kernel`0xc0a9e410

wap_pager_getpages:entry
              0xc4d19f54
              kernel`VOP_READ_APV+0x42
              kernel`vn_read+0x2d4
              kernel`dofileread+0x96
              kernel`kern_readv+0x58
              kernel`read+0x4f
              kernel`syscall+0x366
              kernel`0xc0a9e410

  1  14739        swap_pager_getpages:entry 
              kernel`vm_fault+0x1030
              kernel`vm_fault_wire+0x4a
              kernel`vm_map_wire+0x256
              kernel`vslock+0x1d5
              kernel`sysctl_wire_old_buffer+0x5e
              kernel`sysctl_kern_proc+0x178
              kernel`sysctl_root+0x127
              kernel`userland_sysctl+0x134
              kernel`__sysctl+0xde
              kernel`syscall+0x366
              kernel`0xc0a9e410

色々と出てきた。