やっぱり Sun がスキ！

DTrace の flowindent オプション紹介

今回は、DTrace の flowindent オプションを紹介します。

flowindent オプションは、モニタリングするプログラムに対して、関数の開始(entry)と 終了(return)の出力をインデント(->) を付けて表示させる事により、関数の 入れ子関係を把握しやすくする効果があります。

実際に使用する方法は、 D スクリプトの中に flowindent を定義するか、DTrace 実 行時に -F オプションを付与して実行します。

それでは、実際に flowindent の効果を確認してみましょう。
モニタリングするサンプルとして、下記テストプログラムを実行ファイル名 a.out で作成します。

テストプログラム

int main()
{
    func1();
    func2();
}

int func1()
{
    func3();
}

int func2()
{
    func1();
}

int func3()
{
    func4();
}

int func4()
{
}

テストプログラムに対する関数の入れ子を確認する為に下記 D スクリプト を作成します。今回は、D スクリプトの中に flowindent オプションを 埋め込みました。また、関数の呼び出しを確認する為に pid プロバイダを 使用しております。

サンプル D スクリプト(flowindent.d)

#pragma D option flowindent

pid$target:a.out::entry
{
}

pid$target:a.out::return
{
}

早速 flowindent.d を実行してみましょう。

flowindent.d 実行結果

# dtrace -s flowindent.d -c a.out

dtrace: script 'pid.sample.d' matched 15 probes
dtrace: pid 1196 exited with status 16
CPU FUNCTION
  0  -> _start
  0    -> __fsr
  0    <- __fsr
  0    -> func1
  0      -> func3
  0        -> func4
  0        <- func4
  0      <- func3
  0    <- func1
  0    -> func2
  0      -> func1
  0        -> func3
  0          -> func4
  0          <- func4
  0        <- func3
  0      <- func1
  0    <- func2
  0  <- main

このように、関数の入りと出がインデントを付けて表示されました。
DTrace を使用しないで関数の入れ子状態を確認するデバッグには、よく関数の入りと出の 部分に printf() 文を入れて確認していましたが、DTrace を使用すればソースプログ ラムにデバッグ用のコード を埋め込む修正も必要ないですし、当然、確認の為にリコンパイルも必要ありません。

また、各関数を呼び出した回数や、各関数毎の実行時間の累積も DTrace を使うと 集積関数を使って簡単に計測する事ができます。

関数の呼び出し回数を計測するスクリプト(func_count.d)

pid$target:a.out::entry
{
    @counts[probefunc] = count();
}

pid$target:a.out::return
{
}

func_count.d 実行結果

# dtrace -s func_count.d -q -c a.out

  __fsr                                         1
  _start                                        1
  func2                                         1
  func1                                         2
  func3                                         2
  func4                                         2

このように、各関数を実行した回数を集計して表示する事ができます。

関数の実行時間累積を計測するスクリプト(exectime.d)

pid$target:a.out::entry
{
    self->ts[probefunc] = timestamp;
}

pid$target:a.out::return
/probefunc != "main"/
{
    @sum[probefunc] = sum(timestamp - self->ts[probefunc] );

    self->ts[probefunc] = 0;
}

exectime.d 実行結果

# dtrace -s exectime.d -q -c a.out

  __fsr                                      9923
  func4                                     10553
  func2                                     32865
  func3                                     34526
  func1                                     57725

このように、各関数を実行した累積時間を集計して表示する事ができます。

ここで使用した PID プロバイダは、ユーザが作成したプログラムのパフォーマンス 計測にとても便利ですので、開発者の方は是非マスターして下さい。

---

(参考情報)
過去の 「やっぱり Sun がスキ！」blog 記事一覧はこちらを参照下さい。 http://wikis.sun.com/display/yappri/Home

Posted at 02:12午後 7 24, 2009 by Naoyuki Yamada in Sun  |  投稿されたコメント[0]