TYPO free

home

fighting for TYPO free code

Profiling the extension manager with KCachegrind

4 Aug 2009

Disclaimer:

This is just an example of how to produce profiler output and analyse it, not a real attempt at optimising the extension manager (though that should be done too!).

In the previous article you can read how to install KCachegrind on OSX. If you are on Ubuntu or any other flavour of Linux, chances are that KCachegrind is already shipped with your distribution (apt-get install kcachegrind). Windoze users may use WinCahceGrind. There is also MacCallGrind, but is's not as mature as KCachegrind. KCachegrind is a great GUI on top op Valgrind profiling tools.

Profiling code

A code profiler gives you insight into the inner workings of your code. A profiler allows you to find bottlenecks in your script and visualize those with an external tool such as KCacheGrind or WinCacheGrind. The most we see of code when it is executed is a HTML result displayed on the screen. Some times it takes a while for the HTML to appear on the screen and sometimes it appears almost instantly. Most people prefer the situation in which the HTML appears almost instantly. We programmers must constantly strive to get close to near instant response from the system. Every new version of your software should perform better than the previous.

To get insight into the parts of your code that execute slowly or are called often, you can use a profiler. A profiler notes down the number of times a certain function was called during execution of your code, how long it took to execute, how much memory it used, what functions it was called by and called itself. Some profiler output viewers can also display a callmap that nicely shows this hierarchy.

XDebug

There are several PHP profilers available. XDebug comes with one, Zend Studio comes with one, there is DBG and there is also a profiler developed by the guys from FaceBook. In this article I will discuss XDebug because it's a free, prove solution, It works on PHP 5.3, I have it installed and I am happy with it. I'll leave testing Cachegrind frontends with the output of one of the other profilers as an exercise for the reader.

I never knew XDebug could profile your code too. And I never even thought of profiling PHP code. For me it's a revelation that this is possible and that you can actually see, using numbers and visuals what your code execution looks like.

Enabling XDebug profiler

Enabling the XDebug profiler is done in php.ini or your xdebug.ini if you are lucky enough to have that. Just add the following lines:

[Zend]
xdebug.profiler_output_dir = /Users/yourname/tmp/xdebug
xdebug.profiler_enable_trigger = 1

Make sure you create a directory in a convenient spot where xdebug can dump the profiling results. The webserver user must have write access to that directory.

This configuration will not enable the profiler by default, you can enable the profiling of a certain URI by adding the XDEBUG_PROFILE to the URI or by setting a XDEBUG_PROFILE cookie. There is a configuration option that enables the profiler by default, but it can make browsing your site quite slow. This may be OK in a testing environment, but be aware that a profile data file is created for every request. The file may weigh in between about 50k - 15M or more.

Creating a profile data file

Log into a TYPO3 backend on a TYPO3 4.2 installation and go to the extension manager. There choose the option 'check for extension updates'. I have always found this action very slow to execute and it always annoys me. Now we can use the profiler to see why the action is so slow. When in FireFox, open the resulting frame in a new window so you can add &XDEBUG_PROFILE to the URI in the location bar. Then load that URI again. XDebug will now create a profile data file with a name like 'cachegrind.out.92746', the last number is either the PID (process ID) of the PHP (or Apache) process or the crc32 hash of the directory containing the initially debugged script. If you do a lot of profiling you can find the 'latest' data file by typing the following command in a terminal:

ls -lahtr /Users/yourname/tmp/xdebug

That will show a list of data files, show them with readable file sizes and sort them by creation time, in reverse. The file that was created last will be at the bottom of the list.

Inspect the file

Now we can fire up your GUI:

kcachegrind /Users/yourname/tmp/xdebug/cachegrind.out.92746

This wil present you with a beautiful GUI showing you exactly what is going on. On the left side you find the 'Flat Profile' pane showing all functions in your script sorted by time spend in this function, and all its children. The second column 'Self' shows the time spent in this function (without its children), the third column 'Called' shows how often a specific function was called and the last column 'Function' shows the name of the function.

Xdebug changes internal PHP function names by prefixing the function name with 'php::' and include files are handled in a special way too. Calls to include (and include_once, require and require_once) are followed by '::' and the filename of the included file. The numbers in the first two columns can be either percentages of the full running time of the script (like in the example) or absolute time (1 unit is 1/1.000.000th of a second). You can switch between the two modes with the 'percentage' button. You can find an explanation with pictures on the XDebug profiling page.

What the extension manager should do when 'checking for extension updates' is;

  • find out what extensions are installed on the system and what versions they have
  • check against the repository for updates
  • show results

What actually happens is something different. On my testing system there are a lot of extensions lying around that are not actually 'enabled' in TYPO3. I only have a hand full of extensions actually 'enabled'.

At the top of the function list window, type 'mysql' in the search box. In my case over 8000 mysql queries are performed to find out if there are any updates for my 44 locally installed and active extensions.

You can also sort the function call list by clicking on any of the column headers. To find out what functions were called most, click the 'Called' header. In my case there were 4714 calls to php::Directory->read, 4355 calls to php::is_file, 3214 calls to php::preg_match and 2929 calls to php::unserialize to name a few.

Where is the most time spent

Besides looking at the percentages in the function list, a very useful visualisation tool is the 'Call Graph'. You can find view the graph by clicking on the 'Call Graph' tab in the lower right frame.

As you can see, a lot more is going on than is needed. The extension manager actually starts by looking at 'all available' (not just the 'enabled locally') extensions. And for all installed extensions it also checks to see if the extension was modified locally. Most of the time is spent in searchExtensionsXML. This is the function where 71% of the time is spent on doing database queries. This is a likely candidate for optimization.

Improving the code

Now you can start digging in the code and search for places where you can optimize. When you make changes to your code, you can profile again to see the difference. You can have multiple KCachegrind windows open to compare the results.

Open up the 'filetypo3/mod/tools/em/class.em_xmlhandler.php' and take a look at the function 'searchExtensionsXML'. In that function you will find the following code:

      // Fetch count
$res = $GLOBALS['TYPO3_DB']->exec_SELECTquery('count(*) as cnt', 'cache_extensions', $where);
$row = $GLOBALS['TYPO3_DB']->sql_fetch_assoc($res);
$this->matchingCount = $row['cnt'];
$GLOBALS['TYPO3_DB']->sql_free_result($res);

$res = $GLOBALS['TYPO3_DB']->exec_SELECTquery('*', 'cache_extensions', $where, '', $order, $offset.','.$limit);
$this->extensionsXML = array();
while ($row = $GLOBALS['TYPO3_DB']->sql_fetch_assoc($res)) {
. . .

Using the same $where, two queries are being executed. The first one is only to get the number of results returned from the query. Both are always executed. The amount of queries can be easily reduced by skipping the count(*) query and replacing it with a call to $GLOBALS['TYPO3_DB']->sql_num_rows($res) on the second result set. We change the code to the following and do a new profile run;


    $res = $GLOBALS['TYPO3_DB']->exec_SELECTquery('*', 'cache_extensions', $where, '', $order, $offset.','.$limit);
$this->matchingCount = $GLOBALS['TYPO3_DB']->sql_num_rows($res);
$this->extensionsXML = array();
while ($row = $GLOBALS['TYPO3_DB']->sql_fetch_assoc($res)) {
. . .

When we compare the two profiling runs, we can see in the status bar that our 'total time cost' has gone down from 14.581.497 to 8.339.274. Looking at the number of calls to mysql_query, we see that it has gone down from 829 to 597 queries. Not bad for such a simple code change.

Create a patch

Having found a nice optimization, create a patch and post it to the bugtracker or to forge. Here is the patch: https://bugs.typo3.org/view.php?id=7264

Conclusion

When you make code changes, run the profiler to see if your changes impact the performance of your code. If they negatively effect performance, you must weigh the benefits of the changes to the reduced performance. Have fun!

Update, aug 4 13:54

I looked over the '$limit' statement in the $where clause so my solution is not a proper solution. Thanks for pointing that out Stucki.

Ingo 4 Aug 2009, 13:01
yay! (but still too much for that functionality)
Michiel 4 Aug 2009, 13:11
Sure,

;-) Just an example there . . .
Michael 4 Aug 2009, 13:26
Hi Michiel,

thanks for the nice tutorial, I also like the xdebug / kcachegrind combo very much. Hope to see some more speed improvements in the bugtracker soon...

- michael
Ingo 4 Aug 2009, 13:41
committed to 4.3 trunk :)
Ernesto 17 Aug 2009, 15:47
If you are on Windows but have a Linux development machine, you could run KCacheGrind on your Linux machine, but have X11 directed to your Windows machine:

- install X-Ming Win32, which is a little X11 server for Windows
- connect to your linux machine with SSH and turn on "X11-forwarding" (e.g. in PuTTY Connnection > SSH > X11)

Make sure you have the DISPLAY variable set (should be something like "localhost:10.0") and then just start kcachegrind. It will pop up under Windows and works pretty well.
Commenting is closed for this item