Section 14.5. Profiling with APD

14.5. Profiling with APD

You can use APD (Advanced PHP Debugger) to profile your applications. It is a Zend extension that collects performance statistics during execution of PHP scripts and records them to a file. This file may be analyzed later with the bundled pprofp utility.

APD works by keeping an eye on function calls in your code; each time PHP enters or leaves execution of a function, APD records timing information to a trace file.

After PHP is finished executing the profiled code, you analyze the trace file to determine bottlenecks. This is the interesting part; you quickly learn a lot about your (or other people's) code by analyzing trace files because it gives you a bottom-up view of the application.

14.5.1. Installing APD

You can install APD from PECL simply by running pear install apd. Then, you must load APD into Zend and define a directory for trace dump files. Here's an example php.ini snippet:

 zend_extension = "/usr/lib/php/extensions/20040316/apd.so" apd.dumpdir = "/var/tmp/apd" 

Create the directory, make it writeable for the web server user, and restart the web server:

 shell# mkdir /var/tmp/apd shell# chmod 1777 /var/tmp/apd shell# apachectl restart 

To collect profiling data during execution, call apd_set_pprof_trace() in the beginning of your PHP script.

Tip

To automatically profile all of your scripts, call apd_set_pprof_trace() from a file that is automatically included by the auto_prepend_file php.ini directive.

To selectively profile specific requests, add something like this to your code:

 if ($_GET["_profile"] == "apd") {     apd_set_pprof_trace(); } 

Then, simply add the _profile=apd GET parameter to a request to enable APD profiling. (Use this only for development servers, or you may expose yourself to denial-of-service attacks taking up disk space and eating CPU cycles.)

Set up an application you would like to profile. The following example uses code from the pear.php.net web site.

14.5.2. Analyzing Trace Data

When you have enabled tracing, APD will generate one trace file per request in the dump directory you configured. The trace file will be called pprof.PID, where PID is the process id of the web server process (or standalone parser).

Note

The trace information is appended to the trace file, but the pprofp utility only reads the first trace per file. Clean up the trace files regularly to avoid analyzing old trace data.

Use the pprofp utility to inspect trace files. This example trace output shown in Figure 14.7 originates from analyzing http://pear.php.net/, and pprofp shows which functions and statements that alone consume the most user CPU.

Figure 14.7. Example trace output after analyzing pear.php.net.

There's not much to pick on, but the time spent by require_once (50 percent) indicates that an opcode cache would cut the execution time in half.

The longer the script runs, the more exact data pprofp gives you. Figure 14.8 shows another example that profiles http://pear.php.net/get, which is a PHP script that delivers PEAR package tarballs.

Figure 14.8. Profiling pear.php.net/get.

Once again, an opcode cache would help a lot (60 percent of the time spent by require_once). The peculiar thing here is that calls to define() take 20 percent of the CPU time, which is worth looking into. Even if this is only 12ms in the previous example, everything adds up, and the process of analyzing code in this way is helpful for writing efficient code later.

To find out more about where these define() calls are, use pprofp to generate a call graph:

 $ pprofp -T /var/tmp/apd/pprof.PID main define require_once require_once   require_once     define     define     define     define     define     define     function_exists     zend_version     version_compare     define     substr     define     define     define     ini_set     register_shutdown_function   define (x49) require_once   define (x21)   ... 

Note

APD does not let you see the parameters of the require_once statements here. Xdebug and Zend Studio have this feature, though.

In this graph, the indentation represents a function or statement called within the outer function or statement.

Code inspection lets you figure out the rest. Start immediately after the apd_set_pprof_trace() call, and note the order and depth of the two largest batches of define() calls in the previous graph (49x and 21x). You can see that the 49x batch is called during the second require_once in the top-level script, and the 21x batch is called during the third require_once.

The code just after enabling the trace looks like this:

 if (isset($_GET['_profiler']) && $_GET['_profiler'] == ''apd'') { apd_set_pprof_trace(); } if ($_SERVER['SERVER_NAME'] != 'pear.php.net') {     define('DEVBOX', true); } else {     define('DEVBOX', false); } require_once "pear-cache.php"; // first require_once "DB.php";         // second require_once "DB/storage.php"; // third require_once "pear-config.php"; require_once "pear-auth.php"; require_once "pear-database.php"; 

The first 49 defines are from DB.php; the following 21 are from DB/storage.php.

In PHP 5, defines can be optimized by changing them to const class variables, which are stored as part of the class definition and thus cached by opcode caches. Constants that are defined in script with define() are not cached; instead, the code calling define() is cached and executed every time.

The pprofp program can display more than just user CPU time. Table 14.1 contains a list of command-line options (just type pprofp without any parameters to see it).

Table 14.1. pprofp Options

Option	Description
-l	Sort by the number of calls to each function.
-u	Sort by user CPU time consumed.
-U	Sort by user CPU time consumed, including child calls.
-s	Sort by system CPU time consumed, including child calls.
-S	Sort by system CPU time consumed (system CPU is time spent by the operating system waiting for IO operations, for example).
-z	Sort by user and system CPU time consumed.
-r	Sort by elapsed wall-clock time.
-R	Sort by elapsed wall-clock time, including child calls.
-O n	Display at most n functions (the default is 20).
-t	Display call graph with repeating entries collapsed.
-T	Display uncollapsed call graph.
-i	Ignore PHP built-in functions.