Wednesday, January 6, 2010

Recipe 21.3. Profiling with a Debugger Extension










Recipe 21.3. Profiling with a Debugger Extension



21.3.1. Problem


You want a

robust solution for profiling your applications so that you can continually monitor where the program spends most of its time.




21.3.2. Solution


Use a profiling and debugging extension such as the

Advanced PHP Debugger (APD) or Xdebug, both available from the PECL repository.


With APD installed, adding apd_set_pprof_trace( )
to the top of your script dumps a trace file in a configurable directory. Parsing that trace file gives you a breakdown of how time was spent during that run of the PHP script:


<?php
$dumpdir = '/tmp';
$processid = posix_getpid();
ini_set('apd.dumpdir', $dumpdir);

// Prepare to output a basic report
$dumpfile = $dumpdir . '/pprof.' . $processid . '.0';

// Start the trace
apd_set_pprof_trace();

// Functions that we will profile
function pc_longString() {
return uniqid(php_uname('a'), true);
}

function pc_md5($str) {
return md5($str);
}

function pc_mhashmd5($str) {
return bin2hex(mhash(MHASH_MD5, $str));
}

function pc_hashmd5($str) {
return hash('md5', $str);
}

// Run the functions
$str = pc_longString();

$md5 = function_exists('md5') ? pc_md5($str) : false;
$md5 = function_exists('mhash') ? pc_mhashmd5($str) : false;
$md5 = function_exists('hash') ? pc_hashmd5($str) : false;

echo "now run:\n";
echo " /usr/bin/pprofp -R $dumpfile\n";
echo "to view a report.\n";



Running the report generated by the pprofp tool, which is installed as part of the APD package, results in something like this:


% /usr/bin/pprofp -R /tmp/pprof.16704.0

Trace for /home/clay/phpckbk2/apd/md5.php
Total Elapsed Time = 0.00
Total System Time = 0.00
Total User Time = 0.00


Real User System secs/ cumm
%Time (excl/cumm) (excl/cumm) (excl/cumm) Calls call s/call Memory Usage Name
--------------------------------------------------------------------------------------
100.0 0.00 0.00 0.00 0.00 0.00 0.00 1 0.0005 0.0042 0 main
77.8 0.00 0.00 0.00 0.00 0.00 0.00 1 0.0033 0.0033 33554432
apd_set_pprof_trace
4.6 0.00 0.00 0.00 0.00 0.00 0.00 1 0.0000 0.0002 0 pc_longString
2.6 0.00 0.00 0.00 0.00 0.00 0.00 1 0.0001 0.0001 0 php_uname
2.3 0.00 0.00 0.00 0.00 0.00 0.00 1 0.0000 0.0001 0 pc_mhashmd5
1.5 0.00 0.00 0.00 0.00 0.00 0.00 1 0.0001 0.0001 0 uniqid
1.5 0.00 0.00 0.00 0.00 0.00 0.00 1 0.0000 0.0001 0 pc_md5
1.5 0.00 0.00 0.00 0.00 0.00 0.00 1 0.0001 0.0001 0 mhash
1.3 0.00 0.00 0.00 0.00 0.00 0.00 1 0.0001 0.0001 0 md5
1.3 0.00 0.00 0.00 0.00 0.00 0.00 3 0.0000 0.0000 0 function_exists
1.2 0.00 0.00 0.00 0.00 0.00 0.00 1 0.0000 0.0001 0 pc_hashmd5
1.0 0.00 0.00 0.00 0.00 0.00 0.00 1 0.0000 0.0000 0 hash
0.6 0.00 0.00 0.00 0.00 0.00 0.00 1 0.0000 0.0000 0 bin2hex





21.3.3. Discussion


With APD installed, it's a simple matter to start a profiling session that will store reporting on application runtime. The output files generated by APD can be stored anywhere you want them'even in a dynamic location, if you want to integrate some conditional trace executions into your script. Just use ini_set('apd.dumpdir', '/path/to/writable/dump/directory') to pick a dump location prior to calling apd_set_pprof_trace( ).


The pprof output file is a machine-readable breakdown of how your script was processed. The output file is stored in the apd.dumpdir location with a naming convention of pprof.process ID.file number. The file number portion of the dump file is determined internally by APD, which will create sequential files as needed for each process being traced.


Process the output files with the bundled
pprofp shell application to get some basic insight into what's taking the most time in your application. The longest-running functions are good places to start when looking for opportunities to optimize.


Beyond basic reporting on execution time, the pprof files can be converted to Kcachegrind-compatible files using the
pprof2calltree
conversion tool.
Kcachegrind is a GUI application used to drill down deeply into applications to determine where bottlenecks are occurring.


A number of profiling extensions exist; for the most effective debugging and profiling experience, it's recommended to give each one a try to see which one suits your needs the best.




21.3.4. See Also


Documentation for APD at http://www.php.net/manual/en/ref.apd.php; the Xdebug profiling and debugging extension at http://www.xdebug.org/; the DBG extension at http://dd.cron.ru/dbg/; the Kcachegrind profiling visualization tool at http://kcachegrind.sourceforge.net.













No comments: