Your Apps are Faster!

A few weeks ago I was surprised by a PHP out-of-memory error in the production environment for one of my symfony 1.2 powered sites. This error was being thrown by sfViewCacheManager, the class responsible for deciding whether to render a cached or freshly executed template. The particular line in question generated a "cache key" by running a template's variables through md5(serialize($vars)). This key is then included in a URI that is used to find a cached template.

These are very resource-intensive functions, particularly when passing them large model or form objects. The cause of my problem seemed apparent. I went through my application and added sf_cache_key variables to all my calls to include cached components and partials. With that variable provided by me, symfony would no longer have to run cached paritals' variables through md5(serialize($vars)). Problem solved, right?

No. The errors came back the next day. I dug into the symfony core once again found the root cause for these errors. When the cache was switched on in settings.yml a partial's variables were always passed through md5(serialize($vars)), regardless of whether the cache is enabled for that particular partial in cache.yml. This is why this error was only happening on servers with the cache enabled and why only adding a sf_cache_key variable to cached partials didn't solve the problem.

I wrote a custom partial view class for my application that made sure every partial had at least a random sf_cache_key variable, insuring that md5(serialize($vars)) would never have to be called. That was a temporary fix to keep this particular site online. Today I committed a more reliable fix to all versions of symfony and the performance improvement is quite stunning.

The Benchmarks

To benchmark this improvement I created a very simple project with one action and one partial:

$ mkdir ~/Sites/cache_key_fix
$ cd ~/Sites/cache_key_fix
$ symfony generate:project cache_key_fix
$ symfony generate:app frontend
$ symfony generate:module frontend main

The main/index action is very simple, although you can see I'm passing a very large object to my partial, the sfContext instance.

// apps/frontend/modules/main/actions/actions.class.php
class mainActions extends sfActions
{
  public function executeIndex()
  {
  }
}
 
// apps/frontend/modules/main/templates/indexSuccess.php
<?php for ($i = 0; $i < 100; $i++): ?>
  <?php include_partial('foo', array(
    'foo' => sfContext::getInstance(),
    'bar' => sfContext::getInstance())) ?>
<?php endfor; ?>
 
// apps/frontend/modules/main/templates/_foo.php
<p>foo</p>

The cache key is never generated when the sf_cache setting is disabled, so I enabled that:

# apps/frontend/config/settings.yml
prod:
  .settings:
    cache: on

Since I'm comparing two revisions of symfony, I also added a request variable to the project configuration to be able to switch between checkouts of the core.

// config/ProjectConfiguration.class.php
if (array_key_exists('before', $_GET))
{
  require_once dirname(__FILE__).'/../../sf_before/lib/autoload/sfCoreAutoload.class.php';
}
else
{
  require_once dirname(__FILE__).'/../../sf_after/lib/autoload/sfCoreAutoload.class.php';
}
sfCoreAutoload::register();
 
class ProjectConfiguration extends sfProjectConfiguration
{
}

If you want to run this benchmark comparison on your own project, checkout a before and after copy of the symfony core.

$ svn co http://svn.symfony-project.com/branches/1.2 -r16904 ~/Sites/sf_before
$ svn co http://svn.symfony-project.com/branches/1.2 -r16905 ~/Sites/sf_after

Once the project is in place, hit it once so the config cache is established:

$ curl http://localhost/cache_key_fix/web/index.php/main/index > /dev/null

Now you're ready for the actual benchmarking. Compare the output of the following commands:

$ ab -t 60 -n 20 http://localhost/cache_key_fix/web/index.php/main/index?before
$ ab -t 60 -n 20 http://localhost/cache_key_fix/web/index.php/main/index?after

You should see a significant difference. This is what I got on my MacBook:

Before

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:      289  319  19.4    321     365
Processing:   127  181  54.4    182     388
Waiting:      127  181  54.4    182     387
Total:        462  501  57.0    488     731

After

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:       72  112  60.9     96     308
Processing:     0  143  45.6    157     192
Waiting:        0  143  45.6    157     192
Total:        228  255  24.5    253     347

Whoa. The fastest "before" request (462 ms) is still longer than the slowest "after" request (347 ms), and the mean average shows nearly a 50% decrease in total response time (from 501 to 255 ms).

Of course, these numbers should be taken with a grain of salt. Not all applications pass large objects to partials, although the form object passed around the admin generator templates can be pretty big, depending on what you're storing in your model objects.

Please let us know if you notice any marked performance improvements in any of your applications!