I noticed earlier that our helpdesk system (written in PHP) became somewhat slower after we upgraded to the new version, 1.1. I always thought I’d look into it but never got that far. Of course, I’m using a self-written framework, and I’ve known that it hasn’t been profiled for speed, so I knew there’d be a few things in there that could use a tweaking. So, I fired up a debugger/profiler today and went to work.
XDebug is the premier choice for PHP debugging/profiling. It is available both on Windows and Linux. Just plug it into PHP as a Zend extension, set the configuration to enable profiling, and voila!
zend_extension_ts=”c:/program files/php/ext/php_xdebug.dll”
[xdebug]
xdebug.remote_autostart = 0
xdebug.remote_enable = 0
xdebug.profiler_enable = 1
xdebug.profiler_output_dir = “c:\home\temp\xdebug”
It creates a nice little output file in the output directory. And using WinCacheGrind, it was easy to analyze the logs and see what functions took most of the time.
One little caveat, though – it seemed as though the actual execution time reported by PHP and by XDebug varied by a factor of 10 – a huge difference. But the relative time between function calls indicated by WinCacheGrind was still useful in isolating the time hogs. Just pretend that 466 ms actually is 4.66 s, and there you go.
The result: I discovered that one single function, DateTimeEx::getDateTime, which decodes Excel numeric dates into actual date/time values, stood for a whopping 90% of the total execution time. In this case, there are about 200 objects instantiated from the database, and each of those database objects are called several times to extract date values. So there was a lot of date calculation going on. However, there is no advanced stuff going on (like loops) inside the function, just a bunch of float arithmetic – the only conclusion I can draw is that PHP really sucks when it comes to complex float calculations.
First, I was able to cut down on a few things inside the actual function; and then I made a self-populating date-value cache, holding 300 calculated values.
The result: Execution time for the entire browser request went down from 4.8 seconds to about 650 milliseconds.
Lessons learned:
-
Profiling is invaluable, especially with an interpretative language like PHP, where you never really can be sure what costs time and what doesn’t.
-
XDebug and its companion WinCacheGrind are essential tools and work well on a Windows/Apache platform.
-
PHP is fun, especially when you have powerful tools. :)
Yeah, I noticed that annoying factor 10.
I wonder if that is the fault of wincachegrind, or xdebug itself. Any idea?
I tried to read and make sense of the profiler output file, but I don’t even understand which of the numbers tell me about the duration of function calls.
——–
Another useful thing on windows is to define a file extension for the output files. On my system, all of the files end with “.cachegrind”, which is associated with wincachegrind.
xdebug.profiler_output_name=”request-%R—time-%t.cachegrind”
The %R does not really work, unfortunately..