Web performance debugging with strace, xhprof and php-xdebug

So you may have a PHP web application that's slow. Identifying the bottleneck is hard, and all the usual debug tricks have reached their limits (optimizing MySQL, mysqltuner, slow query logs, css/js file aggregation, caching headers, gzip compression, varnish, etc).

If you have root access to the server: xhprof, xdebug and strace.

First try:

Then try strace. For example:

  • Open "top" in one terminal, look for Apache processes taking a lot of CPU time.

  • Do a request to your web server that you know is slow, and needs debugging. For example, I was having timeouts while saving a Drupal View.

In another (root) terminal, when a process hits a high CPU%, run the following command:

strace -c -p  24198

Where 24198 is the process ID (PID) of the Apache process taking a lot of CPU time.

When your HTTP request is finished, type "Ctrl+C" to interrupt it.

Here is the result I had:

root@myserver:~# strace -c -p  14985
Process 14985 attached - interrupt to quit
^CProcess 14985 detached
% time     seconds  usecs/call     calls    errors syscall
 71.78    0.005433           0     50002           gettimeofday
 11.84    0.000896           2       472         5 stat
  3.92    0.000297           0       993           fstat
  3.82    0.000289           1       222         4 access
  3.08    0.000233           1       361        16 open
  2.88    0.000218           1       221           write
  0.99    0.000075           0       333           munmap
  0.92    0.000070           0       333           mmap
  0.77    0.000058           0       232           poll
  0.00    0.000000           0       301         6 read
  0.00    0.000000           0       351           close
  0.00    0.000000           0       590        22 lstat
  0.00    0.000000           0         1           rt_sigaction
  0.00    0.000000           0         1           rt_sigprocmask
  0.00    0.000000           0        15         1 writev
[...]
100.00    0.007569                 54566        55 total

So, gettimeofday() was using 71% of the CPU time.

Looking around on the web, I found a forum post hinting that this could be a debugger or profiler still running. Ends up that php5-xdebug was at cause.

While my xdebug conf was not profiling by default (it was enabled only if I pass the XDEBUG_PROFILER=1 variable), it seems that it still does some profiling.

If this doesn't help you, I found that looking at the strace output (without "-c") is still often useful. For example, if the APC cache is not working well, the operating system will often stat() the filesystem too often.

Archives