PHP Performance Profiling

At this point you should have APD installed on your server, along with all the other usual stuff--Apache, MySQL or Postgres, your PHP scripts themselves, and whatever else you need to run your Web application.

Now, pick a PHP script in your Web application for a test run, and open it in an editor. In my example here, I use the file src/webmail.php from Squirrelmail, a popular Web mail system written in PHP. The basic procedure is to invoke special APD functions inside your PHP script that tell APD to do its stuff. Right at the top of your PHP script, put in a call to apd_set_pprof_trace(), like this:

        <?php
        apd_set_pprof_trace();
        ...etc

What this does is tell APD to start a trace on execution of your script at that point and dump it out to disk in a predefined location, which is set in the php.ini file using the apd.dumpdir directive. If you used my Debian package, the location should be set to /var/log/php4-apd/; if you used PEAR or compiled from source, please check the included documentation.

Now that your script is set up and ready to profile, load it in a Web browser. It should run exactly as before, and you shouldn't see any difference at all from the client side; the page loads as it always has.

What is different this time is a pprof tracefile has been written out to the dumpdir previously defined. A pprof tracefile is a text file that contains a machine-parsable summary of how your PHP was processed, and it is named something like pprof.25802. The number is the process ID of the Web server process that handled the request. You can take a quick look through the tracefile, but at this point it won't mean much to you. For my example using Squirrelmail, it looks something like this:

        #Pprof [APD] v0.9
        hz=100
        caller=/jade/webserver/site13/web/squirrelmail-1.2.5/src/webmail.php
        
        END_HEADER
        ! 1 /jade/webserver/site13/web/squirrelmail-1.2.5/src/webmail.php
        & 1 main 2
        + 1 1 2
        - 2 98816
        ! 2 /jade/webserver/site13/web/squirrelmail-1.2.5/functions/strings.php
        & 3 require_once 2
        + 3 2 16
        & 4 php_self 2
        + 4 2 597
        @ 1 0 1
        - 4 244352
        - 3 244368
        ! 3 /jade/webserver/site13/web/squirrelmail-1.2.5/config/config.php
        + 3 3 17
        - 3 291224
        ... etc

and so on for several more pages. Essentially it's a step-by-step record of what the Zend engine did as it processed your script, but the format is not designed for direct human consumption. Instead, it's an intermediate log that can be processed to generate nice reports.

APD comes with a little shell script written in PHP, called pprofp, that can be run from the command line to parse the pprof tracefile and give you a human-readable report. To use it, run pprofp and pass it an option and the path of the tracefile, like this:

        pprofp -u /var/log/php-apd/pprof.25802

This command prints out a function call summary that should look something like this:

Trace for /jade/webserver/site13/web/squirrelmail-1.2.5/src/webmail.php
Total Elapsed Time =    0.15
Total System Time  =    0.02
Total User Time    =    0.13
<pre>
         Real         User        System             secs/    cumm
%Time (excl/cumm)  (excl/cumm)  (excl/cumm) Calls    call    s/call  Memory Usage Name
---------------------------------------------------------------------------------------------------------------
 30.8  0.05  0.12   0.04  0.11   0.01  0.01    22   0.0018    0.0050       859752 require_once
 15.4  0.02  0.02   0.02  0.02   0.00  0.00     8   0.0025    0.0025       403200 register_attachment_common
 15.4  0.02  0.02   0.02  0.02   0.00  0.00    23   0.0009    0.0009       298360 define
  7.7  0.01  0.01   0.01  0.01   0.00  0.00     1   0.0100    0.0100       145536 php_self
  7.7  0.01  0.01   0.01  0.01   0.00  0.00     7   0.0014    0.0014       342368 function_exists
  7.7  0.02  0.02   0.01  0.01   0.01  0.01     1   0.0100    0.0100       457224 session_start
  7.7  0.01  0.01   0.01  0.01   0.00  0.00     4   0.0025    0.0025          968 cacheprefvalues
  7.7  0.01  0.01   0.01  0.01   0.00  0.00     1   0.0100    0.0100       163952 is_array
  0.0  0.00  0.01   0.00  0.01   0.00  0.00     4   0.0000    0.0025           64 getpref
  0.0  0.00  0.00   0.00  0.00   0.00  0.00     1   0.0000    0.0000           16 is_logged_in
  0.0  0.00  0.00   0.00  0.00   0.00  0.00     1   0.0000    0.0000         -248 ereg
  0.0  0.00  0.00   0.00  0.00   0.00  0.00     1   0.0000    0.0000           16 set_up_language
  0.0  0.00  0.00   0.00  0.00   0.00  0.00     1   0.0000    0.0000           72 ini_get
  0.0  0.00  0.00   0.00  0.00   0.00  0.00     1   0.0000    0.0000          232 setlocale
  0.0  0.00  0.00   0.00  0.00   0.00  0.00     1   0.0000    0.0000          256 header
  0.0  0.00  0.00   0.00  0.00   0.00  0.00     3   0.0000    0.0000          296 putenv
  0.0  0.00  0.00   0.00  0.00   0.00  0.00     1   0.0000    0.0000           96 getenv
  0.0  0.00  0.00   0.00  0.00   0.00  0.00     1   0.0000    0.0000           56 textdomain
  0.0  0.00  0.00   0.00  0.00   0.00  0.00     1   0.0000    0.0000          424 bindtextdomain
  0.0  0.00  0.00   0.00  0.00   0.00  0.00     1   0.0000    0.0000           56 do_hook

The report above shows time and memory usage on a per-function basis, sorted by user-time as directed by the -u option. The first few columns are execution time in seconds. The Calls column is a count of the number of times that function was executed by the script. secs/call is the average execution time of each call to that function, while cumm s/call is the cumulative time spent on that function. Then it lists memory usage and finally the name of the function itself. Notice that function call reports are truncated to 15 functions by default.

If your script has some major performance problems, here is where they should start to become glaringly obvious. Do you have a slow function that's called many times? Better take a close look at it. Are you doing lots of SQL queries? You can see them here right away.