OpenSolaris の dtrace で PHP のプロファイリングみたいなこと
ということで，前2回は序章で，OpenSolaris上でPHPを動かすことができたので，これでようやくやりたかったことができます．
前2回は以下．
- OpenSolaris の環境構築その1．zshとPHP． - 肉とご飯と甘いもの @ sotarok
- OpenSolaris の環境構築その2．Apache と PHP その他 - 肉とご飯と甘いもの @ sotarok
dtrace のPHPのトレーシングについては，
あたりに，ドキュメントがあったりして，割と簡単にわかる．
というわけで，ざっと使ってみる．
例えば， php_calltime.d
使ってる動画はこんなかんじ．
http://www.screencast.com/users/sotarok/folders/Jing/media/76bf0b0c-f636-4e5c-9b43-66100024e63d
いやまあ，上のドキュメントの最初のサンプルがたまたまcalltime使ってたからこの動画とって見たけど，あんま面白くなかった（ぉ
実際やりたかったものをやろう．
php_flowtime.d
こんなことができる．
実行中のアプリケーションや，当然apache経由で起動したウェブアプリのトレーシングもできる．
以下は，Ethnaの，add-project した直後の状態のflow．Hello, world が出力されてるやつですね．
http://192.168.135.129/ethnatest/ にアクセスしてます．（2.3.6だからPEAR呼んでるな．．．ｗ）
dtraceを起動すると，待ち状態になるので，その状態でPHPにアクセスするとだーっとトレース結果が流れ始める．
emma sotarok% pfexec /opt/DTT/Php/php_flowtime.d C TIME(us) FILE DELTA(us) -- FUNC 1 107219514913 Ethnatest_Controller.php 6 -> main 1 107219518878 Ethna.php 3965 -> main 1 107219521733 PEAR.php 2854 -> main 1 107219525049 PEAR5.php 3316 -> main 1 107219525147 PEAR5.php 98 <- main 1 107219525199 PEAR.php 51 <- main 1 107219525936 Ethna_ActionClass.php 737 -> main 1 107219525987 Ethna_ActionClass.php 50 <- main 1 107219526649 Ethna_ActionError.php 662 -> main 1 107219526697 Ethna_ActionError.php 48 <- main 1 107219542625 Ethna_ActionForm.php 15928 -> main 1 107219542747 Ethna_ActionForm.php 121 <- main 1 107219543678 Ethna_AppManager.php 930 -> main 1 107219544491 Ethna_AppManager.php 813 <- main 1 107219546943 Ethna_AppObject.php 2452 -> main 1 107219547036 Ethna_AppObject.php 93 <- main 1 107219548209 Ethna_AppSQL.php 1173 -> main 1 107219551124 Ethna_AppSQL.php 2915 <- main 1 107219552590 Ethna_AppSearchObject.php 1465 -> main 1 107219553530 Ethna_AppSearchObject.php 939 <- main 1 107219555310 Ethna_Backend.php 1779 -> main 1 107219555373 Ethna_Backend.php 62 <- main 1 107219556590 Ethna_CacheManager.php 1217 -> main 1 107219556646 Ethna_CacheManager.php 56 <- main 1 107219557785 Ethna_Config.php 1139 -> main 1 107219557840 Ethna_Config.php 54 <- main 1 107219588775 Ethna_Controller.php 30934 -> main 1 107219588843 Ethna_Controller.php 68 <- main 1 107219589602 Ethna_ClassFactory.php 758 -> main 1 107219589652 Ethna_ClassFactory.php 50 <- main 1 107219590094 Ethna_DB.php 442 -> main ... 0 107220288580 Ethna_ViewClass.php 143 <- _getTemplateEngine 0 107220288620 Ethna_ViewClass.php 40 <- _getRenderer 0 107220288725 Ethnatest_ViewClass.php 104 -> _setDefault 0 107220288773 Ethnatest_ViewClass.php 48 <- _setDefault 0 107220288930 Ethna_Renderer_Smarty.php 157 -> perform 0 107220290248 Ethna_Util.php 1317 -> is_absolute_path 0 107220290772 Ethna_Util.php 524 <- is_absolute_path 0 107220291257 Smarty.class.php 484 -> display 0 107220291322 Smarty.class.php 65 -> fetch 0 107220292276 Smarty.class.php 953 -> _get_compile_path 0 107220292408 Smarty.class.php 131 -> _get_auto_filename 0 107220293761 Smarty.class.php 1353 <- _get_auto_filename 0 107220293811 Smarty.class.php 49 <- _get_compile_path 0 107220294247 Smarty.class.php 436 -> _is_compiled 0 107220294605 Smarty.class.php 357 -> _fetch_resource_info 0 107220296181 Smarty.class.php 1576 -> _parse_resource_name 0 107220299361 Smarty.class.php 3180 <- _parse_resource_name 0 107220306428 Smarty.class.php 7066 <- _fetch_resource_info 0 107220306678 Smarty.class.php 250 <- _is_compiled 0 107220307053 64cb58e13c267d6fd542a9fad5534556^%%45^45E^45E480CD%%index.tpl.php 374 -> main 0 107220308039 64cb58e13c267d6fd542a9fad5534556^%%45^45E^45E480CD%%index.tpl.php 985 <- main 0 107220309459 Smarty.class.php 1419 <- fetch 0 107220309504 Smarty.class.php 45 <- display 0 107220309555 Ethna_Renderer_Smarty.php 50 <- perform 0 107220309594 Ethna_ViewClass.php 39 <- forward 0 107220312163 Ethna_Controller.php 2569 <- _trigger_WWW 0 107220312271 Ethna_Controller.php 107 <- trigger 0 107220312316 Ethna_Controller.php 44 <- main
次が，例えば，symfonyで，generate:project している様子．ものすごく大変なことをしているのがわかります．
出力例はこんなかんじ．中略してるけど，
emma sotarok% pfexec /opt/DTT/Php/php_flowtime.d [~] C TIME(us) FILE DELTA(us) -- FUNC 0 107423921449 cli.php 16 -> main 0 107423944264 sfCoreAutoload.class.php 22815 -> main 0 107423944537 sfCoreAutoload.class.php 272 <- main 0 107423944656 sfCoreAutoload.class.php 118 -> register 0 107423945341 sfCoreAutoload.class.php 685 -> getInstance 0 107423945484 sfCoreAutoload.class.php 143 -> __construct 0 107423946749 sfCoreAutoload.class.php 1264 <- __construct 0 107423947239 sfCoreAutoload.class.php 490 <- getInstance 0 107423947492 sfCoreAutoload.class.php 252 <- register 0 107423947587 sfCoreAutoload.class.php 95 -> autoload 0 107423983685 sfEventDispatcher.class.php 36097 -> main 0 107423983782 sfEventDispatcher.class.php 97 <- main 0 107423983832 sfCoreAutoload.class.php 49 <- autoload 0 107423983976 sfCoreAutoload.class.php 143 -> autoload 0 107423999373 sfCommandLogger.class.php 15397 -> main 0 107423999460 sfCoreAutoload.class.php 86 -> autoload 0 107424041944 sfConsoleLogger.class.php 42484 -> main 0 107424042008 sfCoreAutoload.class.php 63 -> autoload 0 107424062587 sfStreamLogger.class.php 20579 -> main 0 107424062661 sfCoreAutoload.class.php 73 -> autoload 0 107424079261 sfLogger.class.php 16600 -> main 0 107424079363 sfLogger.class.php 101 <- main 0 107424079414 sfCoreAutoload.class.php 51 <- autoload 0 107424080022 sfStreamLogger.class.php 608 <- main 0 107424080064 sfCoreAutoload.class.php 42 <- autoload 0 107424080439 sfConsoleLogger.class.php 375 <- main 0 107424080482 sfCoreAutoload.class.php 42 <- autoload 0 107424080586 sfCommandLogger.class.php 104 <- main 0 107424080805 sfCoreAutoload.class.php 218 <- autoload 0 107424081212 sfLogger.class.php 407 -> __construct 0 107424081280 sfCommandLogger.class.php 68 -> initialize 0 107424081358 sfEventDispatcher.class.php 77 -> connect 0 107424081905 sfEventDispatcher.class.php 546 <- connect ... 1 107430270782 sfFilesystem.class.php 78 <- canonicalizePath 1 107430270863 sfFilesystem.class.php 81 <- calculateRelativeDir 1 107430270910 sfFilesystem.class.php 46 -> symlink 1 107430271057 sfFilesystem.class.php 147 -> logSection 1 107430271102 sfFilesystem.class.php 44 <- logSection 1 107430271627 sfFilesystem.class.php 525 <- symlink 1 107430271669 sfFilesystem.class.php 42 <- relativeSymlink 1 107430271869 sfPluginPublishAssetsTask.class.php 200 <- installPluginAssets 1 107430271938 sfPluginPublishAssetsTask.class.php 68 <- execute 1 107430272006 sfEvent.class.php 67 -> __construct 1 107430272053 sfEvent.class.php 46 <- __construct 1 107430272094 sfEventDispatcher.class.php 41 -> notify 1 107430272253 sfEvent.class.php 158 -> getName 1 107430272292 sfEvent.class.php 38 <- getName 1 107430272334 sfEventDispatcher.class.php 42 -> getListeners 1 107430272376 sfEventDispatcher.class.php 42 <- getListeners 1 107430272416 sfEventDispatcher.class.php 39 <- notify 1 107430272455 sfBaseTask.class.php 39 <- doRun 1 107430272500 sfTask.class.php 44 <- run 1 107430272555 sfGenerateProjectTask.class.php 54 <- execute 1 107430272649 sfGenerateProjectTask.class.php 94 <- doRun 1 107430272849 sfTask.class.php 200 <- runFromCLI 1 107430272914 sfSymfonyCommandApplication.class.php 64 <- run
中略しましたが，全文はこちら．17000以上のコールがあります．
- symfony の generate:project http://labs.strk.jp/up/symfony_dtrace.txt
- ethna の add-project http://labs.strk.jp/up/ethna_dtrace.txt
などなど
その他ドキュメント見ると，（てか /opt/DTT/ 以下を見ても）いろいろできそうなものがあって夢がひろがります．
プロファイリングとか，いろいろ面白いことができるね！
DTrace楽しいです．＼(^O^)／
