The innocuous variable_set

By Erik, Mon, 10/01/2012 - 01:51
It seems like such a simple piece of code.
variable_set('myvar', 'thevalue');
But it can bring your site to its knees very quickly when used too much.

Overquerying

Recently on a few sites, when they are experiencing extreme slowness or throwing 503 errors we have found a single problem, variable_set();. Trying to trace the issues back, using tools like mytop, we see that there are lots of slow queries and many, many queries of:
select name, value from variable;
But wait! Isn't the variable table cached? We shouldn't be selecting so many times from the variable table if we can get the serialized version of the table from cache.
$cached = cache_get('variables', 'cache_bootstrap');
The problem is that variable_set needs to clear the variables element out of the cache.
cache_clear_all('variables', 'cache_bootstrap');
But every single page request that hits the backend loads the bootstrap.inc file which calls variable_initialize which needs to load the entire variables table. So if the site is under load, we are not only having slow queries for things that are expected to be long, but if one select * from variables starts to back up, then all of the subsequent requests are held until the first one finishes which causes a stampede. So if you're setting variables too often, you're clearing the cached version of the variables table too often, which means extra writes to variables, and updates to cache. And while all of that happens, the cached version isn't available, so any page requests need variables, and therefore start stampeding on the database.

Tracking down the problems

Searching through the code and seeing what variables are being set can help track down what is causing this problem. Sometimes, it's simply a matter of adding some debugging to the variable_set.
function variable_set($name, $value) {
  global $conf;
 
  //adding some debugging 
  syslog('LOG_DEBUG', "$name set to $value");
 
  db_merge('variable')->key(array('name' => $name))->fields(array('value' => serialize($value)))->execute();
 
  cache_clear_all('variables', 'cache_bootstrap');
 
  $conf[$name] = $value;
}
This sends information to the LOG_DEBUG system log which in our hosting is /var/log/debug. If you're going to use this, make sure you know that syslog is running and where LOG_DEBUG will write it's messages. On my local Mac, I just use LOG_NOTICE since I'm not worried about syslog files filling up or getting lost among other processes.

Mitigating Factors

So the good news is that there have been recent developments in core and contrib modules to mitigate this issue. Drupal 7 introduced cache stampede protection for this. Memcache has this as well and so does Pressflow. They help to slow the symptoms, but still don't solve the original problem. Tracking down two variable_sets saved one customer about $10K in hardware costs just making the site respond more efficiently. Find 'em. Fix 'em.

Comments2

Hi Erik,

I just wanted to take a minute to thank you for writing a really helpful blog article. Our Disney Corporate Site uses Drupal and went down recently. The only clue we had was that something was clearing the Bootstrap Cache constantly and clobbering the database. We were really scratching our heads until we stumbled across this blog post. We added your code and within a few minutes had found the culprit. In our case we had a misconfiguration involving the ColorBox Module (https://www.drupal.org/node/2491139) which was very easy to fix. You saved us many many hours of crawling through code on a particularly rough day. So thanks again and have a great week!

John Clarke