読者です 読者をやめる 読者になる 読者になる

肉とビールとパンケーキ by @sotarok

少し大人になった「肉とご飯と甘いもの」

OpenSolaris の dtrace で PHP のプロファイリングみたいなこと

OpenSolaris DTrace PHP

ということで,前2回は序章で,OpenSolaris上でPHPを動かすことができたので,これでようやくやりたかったことができます.
前2回は以下.


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呼んでるな...w)


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以上のコールがあります.

などなど

その他ドキュメント見ると,(てか /opt/DTT/ 以下を見ても)いろいろできそうなものがあって夢がひろがります.
プロファイリングとか,いろいろ面白いことができるね!

DTrace楽しいです.\(^O^)/