Profiling with Xdebug

A profile records how long each function took; a trace logs every call with its arguments and return value. report.php totals 500 carts of 20 lines over a 2,000-book catalog. Profile mode writes a gzipped cachegrind.out.<pid>.gz, which KCachegrind 126 or QCachegrind draw as call graphs and Valgrind 79,530 's callgrind_annotate summarizes:

php -d zend_extension=xdebug -d xdebug.mode=profile -d xdebug.output_dir=/tmp/prof report.php
zcat /tmp/prof/cachegrind.out.*.gz > /tmp/prof/cg.out && callgrind_annotate /tmp/prof/cg.out

...
7,338,950 (100.0%) 3,260,672 (100.0%)  PROGRAM TOTALS
...
3,017,319 (41.11%)         0           report.php:{main}
1,213,114 (16.53%)   477,072 (14.63%)  src/Cart.php:Acme\Shop\Cart->totalCents
...

The unit is 10 ns (73 ms in all); these self costs show the loop in {main} outweighed any method.

php -d zend_extension=xdebug -d xdebug.mode=trace -d xdebug.start_with_request=yes \
  -d xdebug.output_dir=/tmp/prof -d xdebug.use_compression=0 -d xdebug.collect_return=1 \
  -d xdebug.var_display_max_depth=0 -d xdebug.trace_output_name=trace trace.php
cat /tmp/prof/trace.xt

...
    0.0003     475208     -> Acme\Shop\Cart->totalCents() /app/trace.php:10
    0.0004     475208       -> Acme\Shop\Catalog->find($sku = 'BK-SQL-02') /app/src/Cart.php:16
    0.0004     475208        >=> class Acme\Shop\Product { ... }
    0.0004     475208      >=> 5800
...

Columns are seconds, bytes and the call, indented by depth; >=> marks a return value.