Web performance debugging with strace, xhprof and php-xdebug
Contents
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:
- xhprof https://wiki.koumbit.net/DrupalPerformance or
- php5-xdebug. https://wiki.koumbit.net/XdebugEn
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.
Author Mathieu Lu
LastMod 2013-02-01