- date
2011-12-12 00:03:54
- slug
21
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 サポート付きでコンパイルします:
$ cd /path/to/php-5.4
$ ./configure --enable-dtrace
$ make
$ make installインストールが完了したら、 DTrace サポートが有効になっているかを確認します:
$ php-5.4.0RC3 -i | grep -i 'dtrace support'
DTrace Support => enabledDTrace では、プログラムに埋め込まれた「プローブ」と呼ばれる計測ポイントを用い、追跡をおこないます。
現在利用可能なプローブの一覧は 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-shutdownfunction-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 時間を表す vtimestamp、 function-entry の第 1 引数を表す組み込み変数 arg0 を copyinstr() 関数によって文字列に変換した値をフォーマットして出力しています。
同様に、 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 アクションの基本 - DTrace ユーザーガイド
- 第 3 章 変数 :: 組み込み変数 - Solaris 動的トレースガイド
- 第 10 章 アクションとサブルーチン - Solaris 動的トレースガイド
ここまでで、「なんかすごそうなことはわかったけど、いますぐ使えそうな気がしない」と感じた方もいらっしゃることでしょう。
そんなあなたには、 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わあ、なんかすごい！
手元では 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 閲覧）
- DTrace - Wikipedia, the free encyclopedia
- Introduction - DTrace - wikis.sun.com
- DTrace ユーザーガイド
- http://docs.oracle.com/cd/E19253-01/819-0395/index.html
- DTrace Topics Intro - Siwiki
- Dynamic Tracing of your AMP web site
- New DTrace probes within PHP in OpenSolaris 2009.06 (Sriram Natarajan's Weblog)
- 奥野 幹也 著 『エキスパートのためのMySQL[運用+管理]トラブルシューティングガイド』 技術評論社, 2010 年 （なんと、第 4 章がまるまる DTrace のために設けられています（全 7 章）。とてもわかりやすい説明ですので、 DTrace の参考書籍としても是非オススメしたいです）