DTrace で PHP スクリプトの動作を追跡する (PHP 5.4 Advent Calendar 2011 12 日目)

PHP 5.4 Advent Calendar 2011 12 日目です。 前回は Paul さん でした。 Trait は今すぐにでも使いたい機能のうちのひとつですよね!

さて、 PHP 5.4 では DTrace がサポートされました。 DTrace は、稼働中のシステムの動作に関する情報を動的に追跡、解析するための仕組みです。元々は Soralis のために開発されたものですが、現在では Mac OS X や FreeBSD でも利用可能です。

DTrace を使うことにより、プログラムの動作の調査やパフォーマンス上の問題の検出などを、ソースコードを変更することなくおこなうことができます。計測の際にプログラムの停止や再起動の必要がないことや、 DTrace を使用していないときに DTrace 用のコードがパフォーマンスにおよぼす影響はわずかであることから、実際のシステムが稼働している環境で試しやすいのも魅力的です。

ですが、ここでいきなり残念なお知らせがあります。

DTrace は Solaris 10 以降や Mac OS X 10.5 (Leopard) 以降、 Free BSD 7.1 以降などの環境で利用できるようですが、 Linux ではまだちょっと難しい状況のようです。僕が謝るようなことではないですが、なんだかごめんなさい><

Linux への移植については進んでいる ようで、 最近 Oracle Linux に追加された ようですが、 現状の実装には、利用可能なプローブが少なすぎるなどの問題が存在する ようです。しかし、本当に楽しみな動きであることには間違いありません。今後に期待したいところですね!

ちなみにこのブログ記事で紹介する内容はすべて Mac OS X 10.7 (Lion) で試したときのものです。 OS X では初期状態で DTrace が利用可能なようです。環境によっては別途インストールの必要があるかもしれないので、そのあたりは各自ご対応ください。

PHP 5.4 を DTrace サポート付きでコンパイルする

さて、まずは PHP 5.4 を DTrace サポート付きでコンパイルします:

$ cd /path/to/php-5.4
$ ./configure --enable-dtrace
$ make
$ make install

インストールが完了したら、 DTrace サポートが有効になっているかを確認します:

$ php-5.4.0RC3 -i | grep -i 'dtrace support'
DTrace Support => enabled

PHP 5.4 で利用可能なプローブを確認する

DTrace では、プログラムに埋め込まれた「プローブ」と呼ばれる計測ポイントを用い、追跡をおこないます。

現在利用可能なプローブの一覧は dtrace コマンドを -l で実行することで確認することができますが、量が多いのでまずはどのくらいのプローブが利用可能か確認してみましょう:

# dtrace -l | wc -lh
162083

はい、想像以上の量でしたね。ということで数行だけちょっと覗いてみましょう:

# dtrace -l | head
ID   PROVIDER            MODULE                          FUNCTION NAME
 1     dtrace                                                     BEGIN
 2     dtrace                                                     END
 3     dtrace                                                     ERROR
 4   lockstat       mach_kernel                      lck_mtx_lock adaptive-acquire
 5   lockstat       mach_kernel                      lck_mtx_lock adaptive-spin
 6   lockstat       mach_kernel                  lck_mtx_try_lock adaptive-acquire
 7   lockstat       mach_kernel             lck_mtx_try_spin_lock adaptive-acquire
 8   lockstat       mach_kernel                    lck_mtx_unlock adaptive-release
 9   lockstat       mach_kernel                  lck_mtx_ext_lock adaptive-acquire

利用可能なプローブが各行にひとつずつ列挙されています。各列の説明を簡単にします。

  • PROVIDER は、このプローブの「プロバイダ」を表します。ありていに言えばプローブを提供するプログラムの識別子のようなものです。
  • MODULE は、プローブが属する「モジュール」を表します。カーネルモジュール名やライブラリ名が入ります。上の例のように、存在しない場合もあります。
  • FUNCTION は、プローブが属するプログラムの関数名を表します。上の例のように、存在しない場合もあります。
  • NAME は、プローブの機能を表す名前を表します。

プローブは、これらの 4 項目をコロンで区切ることによって識別します。たとえば上の例の ID 4 番のプローブ名は lockstat:mach_kernel:lck_mtx_lock:adaptive-acquire となります。モジュール名と関数名を持たない 1 番のプローブ名は dtrace:::BEGIN となります。

プローブ名やプロバイダ名などを指定し、利用するプローブを絞り込むことができます。たとえば dtrace プロバイダのプローブの一覧のみを得たい場合、以下のようにします:

# dtrace -l -P 'dtrace'

プロバイダ名やプローブ名にワイルドカードを指定して絞り込むこともできます:

# dtrace -l -n 'lockstat:mach_kernel:*:*-acquire'

では、これを使って PHP 独自のプローブの一覧を出力してみましょう。ただし、この時点では、 PHP 独自のプローブを検出することはできません。ユーザプログラムのプローブを検知するためには、プロセスを立ちあげておく必要があるようです。

ということで、せっかくなので、 PHP 5.4 から追加されることになるビルトインウェブサーバーで試してみることにしましょう:

$ php-5.4.0RC3 -S localhost:8080

この状態で、以下のようにプローブを出力します:

# dtrace -l -P 'php*'
   ID   PROVIDER            MODULE                          FUNCTION NAME
167429   php96586      php-5.4.0RC3               dtrace_compile_file compile-file-entry
167430   php96586      php-5.4.0RC3               dtrace_compile_file compile-file-return
167431   php96586      php-5.4.0RC3                        zend_error error
167432   php96586      php-5.4.0RC3  ZEND_CATCH_SPEC_CONST_CV_HANDLER exception-caught
167433   php96586      php-5.4.0RC3     zend_throw_exception_internal exception-thrown
167434   php96586      php-5.4.0RC3                    dtrace_execute execute-entry
167435   php96586      php-5.4.0RC3           dtrace_execute_internal execute-entry
167436   php96586      php-5.4.0RC3                    dtrace_execute execute-return
167437   php96586      php-5.4.0RC3           dtrace_execute_internal execute-return
167438   php96586      php-5.4.0RC3                    dtrace_execute function-entry
167439   php96586      php-5.4.0RC3                    dtrace_execute function-return
167440   php96586      php-5.4.0RC3              php_request_shutdown request-shutdown
167441   php96586      php-5.4.0RC3               php_request_startup request-startup

プローブの名前から、なんとなく役割は想像できますね。以下、簡単に説明します。

  • compile-file-* : Zend Engine が PHP スクリプトをコンパイルしたタイミングで実行
  • function-* : 関数をコールするタイミングで実行
  • execute-* : zend_execute() がコールされたタイミングで実行
  • exception-* : 例外の throw / catch のタイミングで実行
  • error : PHP でエラーが発生したタイミングで実行
  • request-* : PHP スクリプトの実行時 / 終了時に実行

ちなみに、これらのプローブの定義は Zend/zend_dtrace.d から確認することができます。こちらのファイルからはプローブで利用可能な引数も確認することができます( dtrace コマンドに -v オプションをつけてもよい)。実際に DTrace のための処理がおこなわれる場所は、 HAVE_DTRACE あたりをキーワードにソースコードを検索すると確認できると思います。

プローブを有効にしてみる

ということで、 PHP 独自のプローブを早速有効にしてみましょう。

以下のスクリプトをビルトインウェブサーバから実行することを考えます:

<?php

function foo()
{
    try {
        throw new RuntimeException('黒歴史');
    } catch (Exception $e) {
    }

    sleep(1);

    bar();
}

function bar()
{
    sleep(2);
}

foo();

まずは、関数コールのタイミングで発行される function-entry プローブの例を示します。方法は簡単で、プローブ名を指定するだけです:

$ dtrace -n 'php*:*:dtrace_execute:function-entry'
dtrace: description 'php*:*:dtrace_execute:function-entry' matched 1 probe

これで、 DTrace は指定したプローブが発行されるのを待つようになります。この状態で、サーバにリクエストをおこなうと、以下のような出力がおこなわれるはずです:

CPU     ID                    FUNCTION:NAME
  0 167438    dtrace_execute:function-entry
  0 167438    dtrace_execute:function-entry

見事に関数コールを検知しているのがわかりますね。

今度は request-shutdown プローブを有効にして試してみます:

$ dtrace -n 'php*:*:php_request_shutdown:request-shutdown'
dtrace: description 'php*:*:php_request_shutdown:request-shutdown' matched 1 probe
CPU     ID                    FUNCTION:NAME
  0 167440 php_request_shutdown:request-shutdown

function-entry が検知されなくなった代わりに、 request-shutdown が出力されるようになりました。

プローブは複数指定することもできます:

$ dtrace -n 'php*:*:dtrace_execute:function-entry php*:*:php_request_shutdown:request-shutdown'
dtrace: description 'php*:*:dtrace_execute:function-entry php*:*:php_request_shutdown:request-shutdown' matched 2 probes
CPU     ID                    FUNCTION:NAME
  1 167438    dtrace_execute:function-entry
  1 167438    dtrace_execute:function-entry
  0 167440 php_request_shutdown:request-shutdown

と、まあ、これだけだとありがたみがないと思うので、プローブから取得できる情報も出力してみましょう。

function-entry は第 1 引数に関数名が格納されている ので、この情報を以下のようにして出力してみます:

$ dtrace -n 'php*:*:dtrace_execute:function-entry { printf("%Y %d %s", walltimestamp, vtimestamp, copyinstr(arg0)) }'
dtrace: description 'php*:*:dtrace_execute:function-entry ' matched 1 probe
CPU     ID                    FUNCTION:NAME
  1 167438    dtrace_execute:function-entry 2011 Dec 10 18:20:20 1288014970 foo
  1 167438    dtrace_execute:function-entry 2011 Dec 10 18:20:21 1288087942 bar

-n オプションで指定されているプローブ名の直後に、波括弧に囲われた記述が追加されています。 DTrace の出力にも、日付と関数名が加わっているのがわかります。

波括弧に囲われた記述は「アクション」と呼ばれているものです。プローブが発行されると、ここで指定されたアクションが実行されます。ここでは、 printf() 関数によって、プローブの発行時刻を表す組み込み変数である walltimestamp と、 CPU 時間を表す vtimestampfunction-entry の第 1 引数を表す組み込み変数 arg0copyinstr() 関数によって文字列に変換した値をフォーマットして出力しています。

同様に、 exception-caught でも似たようなことをやってみましょう。このプローブは例外の捕捉タイミングで発行され、 引数にクラス名のみを持ちます

$ dtrace -n 'php*:*:ZEND_CATCH_SPEC_CONST_CV_HANDLER:exception-caught { printf("%Y %s", walltimestamp, copyinstr(arg0)); ustack(); }'
dtrace: description 'php*:*:ZEND_CATCH_SPEC_CONST_CV_HANDLER:exception-caught ' matched 1 probe
CPU     ID                    FUNCTION:NAME
  1 167432 ZEND_CATCH_SPEC_CONST_CV_HANDLER:exception-caught 2011 Dec 10 10:48:07 RuntimeException
          php-5.4.0RC3`ZEND_CATCH_SPEC_CONST_CV_HANDLER+0xc2
          php-5.4.0RC3`execute+0x281
          php-5.4.0RC3`dtrace_execute+0x11c
          php-5.4.0RC3`zend_do_fcall_common_helper_SPEC+0x562
          php-5.4.0RC3`execute+0x281
          php-5.4.0RC3`dtrace_execute+0x11c
          php-5.4.0RC3`zend_execute_scripts+0x1b8
          php-5.4.0RC3`php_execute_script+0x2d2
          php-5.4.0RC3`php_cli_server_recv_event_read_request+0x64b
          php-5.4.0RC3`do_cli_server+0xc25
          php-5.4.0RC3`main+0x1554
          php-5.4.0RC3`start+0x34
          php-5.4.0RC3`0x6

例外クラス名と例外の捕捉された時刻、スタックトレースを表示しています。

なんだかいろいろできそうな気がしてきましたね!

関数や組み込み関数についての詳細は、以下のドキュメントを参考にしてください。

DTrace Toolkit のご紹介

ここまでで、「なんかすごそうなことはわかったけど、いますぐ使えそうな気がしない」と感じた方もいらっしゃることでしょう。

そんなあなたには、 DTrace Toolkit をお勧めします! これさえあれば、手軽に DTrace のすごさを実感できます。

DTrace Toolkit は、 Brendan Gregg 氏によって開発された、 DTrace のスクリプト集です。

http://www.brendangregg.com/DTraceToolkit-0.99.tar.gz から入手できるアーカイブを展開すると、 Php というディレクトリ があるのがわかると思います。なんと、もう既に PHP 用のスクリプトが用意されているのです。ありがたい話ですね!

その中から、 php_calltime.d を実行してみることにしましょう。これは、各関数の実行にかかった実時間を出力するスクリプトです:

$ /path/to/DTraceToolkit-0.99/Php/php_calltime.d
Tracing... Hit Ctrl-C to end.

この状態でスクリプトを実行し、 Ctrl-C をタイプしてトレースを終了させると、以下のように結果が出力されます:

Count,
   FILE                 TYPE       NAME                                COUNT
   example.php          func       bar                                     1
   example.php          func       foo                                     1
   -                    total      -                                       2

Exclusive function elapsed times (us),
   FILE                 TYPE       NAME                                TOTAL
   example.php          func       foo                               1001553
   example.php          func       bar                               2006856
   -                    total      -                                 3008410

Inclusive function elapsed times (us),
   FILE                 TYPE       NAME                                TOTAL
   example.php          func       bar                               2006856
   example.php          func       foo                               3008410

わあ、なんかすごい!

関数コール中にシステムコール mmap() が割り当てたメモリの容量を報告する D 言語プログラムを書いてみる (D 言語 Advent Calendar 1 日目)

手元では php_malloc.d がうまく動かなかったので、いろいろ試行錯誤したところ、 PHP 5.3 のリリースマネージャである Johannes Schlüter 氏_emalloc() 関数のコールを pid$target::_emalloc:entry というプローブで検出するアプローチを 紹介 しておられるのを見つけました。

これを参考に、 _emalloc() が呼ばれるたびに、割り当てたメモリとスタックトレースを出力するスクリプトを書いたので、ちょっと試してみます:

$ cat /tmp/memory.d
#!/usr/sbin/dtrace -Z -s

pid$target::_emalloc:entry
{
    printf("_emalloc called, allocating %i bytes\n", arg0);
    ustack();
}

$ cat /tmp/example.php
<?php

var_dump(phpversion());

$ /tmp/memory.d -c "php-5.4.0RC3 -n /tmp/example.php"
dtrace: script '/tmp/memory.d' matched 1 probe
string(8) "5.4.0RC3"
CPU     ID                    FUNCTION:NAME
  0 175636                   _emalloc:entry _emalloc called, allocating 4 bytes

              php-5.4.0RC3`_emalloc
              php-5.4.0RC3`zend_stack_push+0x63
              php-5.4.0RC3`ini_lex+0x5f1
              php-5.4.0RC3`ini_parse+0x11c
              php-5.4.0RC3`zend_parse_ini_string+0x47
              php-5.4.0RC3`php_init_config+0x81b
              php-5.4.0RC3`php_module_startup+0x7c8
              php-5.4.0RC3`php_cli_startup+0x14
              php-5.4.0RC3`main+0x462
              php-5.4.0RC3`start+0x34
              php-5.4.0RC3`0x3

このスクリプトは D 言語で記述されています。 D Programing Language ではなく、 D Language です。

先ほど紹介した DTrace Toolkit も、 -n オプションでプローブを指定した際に記述したアクションも、実は D 言語で書かれていました。

オプションでスクリプトを記述する場合に比べ、D 言語のスクリプトファイルを DTrace に実行させることで、複雑なロジックを書きやすくなったり、ロジックの再利用ができるようになったりといったメリットを享受することができます。これも、 DTrace の強みと言えるでしょう。

さて、前述のスクリプトなのですが、手元で試すと、報告されるメモリの使用量の合計が実感とあわなかったり、そもそも一度も _emalloc() のコールを検知できなかったりといった問題に遭遇しました。

そこで、関数コール中に呼ばれた mmap() で割り当てられたメモリの容量を集計していくスクリプトを書いてみたので、以下に示します。 D 言語の書き方についてはこのエントリでは紹介しませんが、適宜コメントを書いておいたので、理解の手助けにしていただければと思います:

#!/usr/sbin/dtrace -C -Z -s

#pragma D option quiet

/*
    C オプションをつけることで、 C コンパイラのプリプロセッサが利用可能になる
    (http://docs.oracle.com/cd/E19253-01/819-0395/chp-prog-5/index.html)
*/

#define BEGIN_ENTRY() \
    self->depth++;\
    self->mu[self->depth] = 0

#define END_ENTRY() \
    this->mu = self->mu[self->depth];\
    self->mu[self->depth] = 0;\
    self->depth--

php*:*:php_request_startup:request-startup
{
    /* php_request_startup:request-startup の第 2 引数は request_uri, 第 3 引数は request_method */
    printf("[%Y] request startup: %s %s\n", walltimestamp, copyinstr(arg2), copyinstr(arg1));

    /*
        識別子 self に -> 演算子でアクセスすることで、スレッド固有変数を参照できる
        (http://docs.oracle.com/cd/E19253-01/819-0395/chp-variables/index.html#6n2qtsp8n)
    */
    self->memory = 0;

    BEGIN_ENTRY();
}

php*:*:dtrace_execute:function-entry
{
    BEGIN_ENTRY();
}

php*:*:dtrace_execute:function-return
/ self->mu[self->depth] >= 131072 /
{
    /* 2 ^ 17 bytes 以上のメモリアロケーション時にのみ出力 */

    END_ENTRY();

    printf("[%Y] PID: %d, function: %s, file: %s, line: %d, allocated: %d\n", walltimestamp, pid, copyinstr(arg0), copyinstr(arg1), arg2, this->mu);
}

php*:*:dtrace_execute:function-return
/ self->mu[self->depth] < 131072 /
{
    END_ENTRY();
}

php*:*:php_request_shutdown:request-shutdown
{
    END_ENTRY();

    printf("[%Y] PID: %d, function: main(), memory: %d\n", walltimestamp, pid, self->memory);
}

syscall::mmap:entry
/ curpsinfo->pr_fname == "php-5.4.0RC3" /
{
    self->memory += arg1;
    self->mu[self->depth] += arg1;
}

おわりに

最後に、もうひとつ残念なお知らせがあります。「残念」というのは僕にとってなんですけど。

なんと、この DTrace のサポートははるか昔に PHP 拡張として提供されていたのです。

http://pecl.php.net/package/DTrace

どおりで都合よく DTrace Toolkit に PHP 用のスクリプトがいるわけだ! まったく新しい話ではなかったわけだ!

えーと……

ま、まあ……デフォルトでサポートされるようになったので、これから有用なプローブが増えるかもしれませんしね! というか http://svn.php.net/viewvc/pecl/dtrace/trunk/php.d?revision=192374&view=markup 見る限りだと PHP 拡張の DTrace は関数の実行に関するプローブしか提供されていませんしね! 黒歴史の例外とか捕捉しても検知できないしね! しかも現時点で拡張で提供されているということは、今から DTrace での PHP の追跡に慣れておけば、 PHP 5.4 以降でジャンジャカとプローブが増えたときでもすぐに使いこなせるということですよ! むしろいいことじゃないですか!(バンバンと机を叩きながら)

気を取り直して、次は……あれ!? 次の担当の方がいらっしゃらない……?

ということで PHP5.4 Advent Calendar 2011 は参加者大絶賛募集中です! 人の集まりが悪いようなら来週あたりもう 1 エントリ書こうと思います!><

参考文献

(URL はすべて 2011/12/11 閲覧)

comments powered by Disqus

Recently entries