PHP Performance Tuning Timing Program Execution by Function

PHP Performance Tuning

Timing Program Execution by Function

Problem

You have a block of code and you want to profile it to see how long each function takes to execute.

Solution

Use Xdebug function tracing:

       xdebug_start_trace('/tmp/factorial-trace');

    

       function factorial($x) {

              return ($x == 1) ? 1 : $x * factorial($x - 1);

       }

       print factorial(10);

       xdebug_stop_trace();

Discussion

The Xdebug extension provides a wide range of helpful debugging and profiling features. It’s available via PECL or as a prebuilt Windows binary.

Its function-tracing feature provides insight into what functions are called from where, optionally including the arguments passed and returned. It also records the time and memory taken for each call.

For the factorial example, it generates results such as:

   TRACE START   [2015-01-05 06:32:11]

        0.0005                    240136       -> factorial($x = 10) /factorial.php:9

        0.0005                    240184         -> factorial($x = 9) /factorial.php:6

        0.0005                    240256           -> factorial($x = 8) /factorial.php:6

        0.0006                    240304            -> factorial($x = 7) /factorial.php:6

        0.0006                    240352              -> factorial($x = 6) /factorial.php:6

        0.0006                    240400               -> factorial($x = 5) /factorial.php:6

        0.0007                    240448                  -> factorial($x = 4) /factorial.php:6

        0.0007                    240496                    -> factorial($x = 3) /factorial.php:6

        0.0007                    240544                      -> factorial($x = 2) /factorial.php:6

        0.0008                   240592                         -> factorial($x = 1) /factorial.php:6

                                                                                  >=> 1

                                                                                >=> 2

                                                                              >=> 6

                                                                            >=> 24

                                                                          >=> 120

                                                                        >=> 720

                                                                      >=> 5040

                                                                    >=> 40320

                                                                  >=> 362880

                                                                >=> 3628800

        0.0010                    240136      -> xdebug_stop_trace() /factorial.php:12

        0.0010                    240176

   TRACE END   [2015-01-05 06:32:11]

The first column lists the start time in seconds. The next column has the memory usage. Then you see the function called, along with the argument passed. Finally, it lists the filename and line number. As the functions execute, you see the data returned from each one.

Xdebug allows you to format these results in a number of ways. This specific output format uses the following configuration parameters:

       xdebug.trace_format=0      ;  human readable plain text

       xdebug.collect_params=4  ;  full variable contents and variable name.

       xdebug.collect_return=1     ;  show return values

Xdebug’s function profiling provides an easy way to get a detailed overview of everything going on in a section of code. However, there are times when this may be more granular than you need.