Seem to be experiencing a performance issue with latest version of this module. Not entirely sure this should be listed as a bug/major, as surprised no-one else has yet reported an issue of this kind, and in so believe the problem could be related specifically to my setup.

Previously running 7.x-1.5 for a particular page I had a TTFB average < 2 secs.

Running 7.x-1.6 for the same page, I see a TTFB ~15secs

Several times I have reverted and re-applied the module update and the results are consistent.

I have a multisite setup and run memcache across two servers.

I have attempted setting the memcache_persistent to false for the updated module but this makes very little difference.

Anyone any idea on what might be causing such a significant jolt in performance from one version to the next? Have I missed a piece of config or any other suggestions?

The configuration remains the same as below across the two versions of the module:

$conf['cache_class_cache_form'] = 'DrupalDatabaseCache';

// based on whether memcache should be enabled for environment
// if enabled for the env, memcache_servers is set to an array of server IPs otherwise it is set to false.
$memcache_servers = $env_info['memcache'];

if(isset($memcache_servers) && $memcache_servers !== false) {

  $conf['cache_backends'][] = 'sites/all/modules/contrib/memcache/memcache.inc';
  $conf['cache_default_class'] = 'MemCacheDrupal';
  $conf['lock_inc'] =  'sites/all/modules/contrib/memcache/memcache-lock.inc';
  $conf['memcache_stampede_protection'] = TRUE;
  $conf['memcache_key_prefix'] = $db;
  $conf['page_cache_invoke_hooks'] = TRUE;
  $conf['page_cache_without_database'] = FALSE;

 $conf['memcache_bins'] = array(
    'cache'        			=> 'default',
    'cache_admin_menu'		=> 'default',
    'cache_metatag'   		=> 'default',
    'cache_rules'  			=> 'default',  
    'cache_reports'  		=> 'default',  
    'cache_libraries'   	=> 'default',
    'cache_media_xml'   	=> 'default',
    'cache_search_api_solr' => 'default',
    'cache_ultimate_cron' 	=> 'default',
    'cache_token' 			=> 'default',	
    'cache_update' 			=> 'default',
    'cache_filter' 			=> 'default',
    'cache_image'   		=> 'default',
    'cache_block'  			=> 'block',
    'cache_bootstrap' 		=> 'bootstrap',
    'cache_field' 			=> 'field',
    'cache_entity_file'		=>'entity',
    'cache_entity_node'		=>'entity',
    'cache_entity_taxonomy_term' =>'entity',
    'cache_entity_taxonomy_vocabulary' =>'entity', 
    'cache_entity_user'		=>'entity',
    'cache_menu'   			=> 'menu',
    'cache_path'   			=> 'path',
    'cache_page' 			=> 'page',
    'cache_views'  			=> 'views',
    'cache_views_data' 		=> 'views',
    'cache_panels'			=> 'panels',
  );
  
  foreach($memcache_servers as $k => $server) {
    $conf['memcache_servers'][$server.':11211'] = 'default';
    $conf['memcache_servers'][$server.':11212'] = 'block';
    $conf['memcache_servers'][$server.':11213'] = 'bootstrap';
    $conf['memcache_servers'][$server.':11214'] = 'field';
    $conf['memcache_servers'][$server.':11215'] = 'entity';
    $conf['memcache_servers'][$server.':11216'] = 'menu';
    $conf['memcache_servers'][$server.':11217'] = 'path';
    $conf['memcache_servers'][$server.':11218'] = 'page';
    $conf['memcache_servers'][$server.':11219'] = 'views';
    $conf['memcache_servers'][$server.':11220'] = 'panels';
  }
 }

Comments

deranga created an issue. See original summary.

jeremy’s picture

It sounds like the locking layer. Perhaps first try disabling Stampede Protection (comment it out from your settings.php). If that doesn't work, also comment out the memcache-lock.inc line.

If either works then we know where to dig further to track down the problem.

deranga’s picture

Hi Jeremy,

Thx for quick reply. Hope your 2 yr old is doing well, have 10 mnth old myself ;)

The first item appears to have done the trick:

$conf['memcache_stampede_protection'] = FALSE;

Can I help with the debugging?

Cheers

Lee

jeremy’s picture

Thanks -- I hope you're enjoying! :)

Ok, it's nice to have isolated the problem so quickly. Next we need to figure out which lock. The simplest thing will probably be to enable the debug log with verbose logging (http://cgit.drupalcode.org/memcache/tree/README.txt#n506), and if you could upload (or send me directly via email to jeremy at tag1consulting.com) the log. It shouldn't contain anything sensitive unless your keys themselves are sensitive -- it doesn't log the actual cache values; it's a new feature though and I've not reviewed it closely for leaking sensitive data.

I'll try and review tomorrow, I'm dropping offline now, speaking of the toddler ...

jeremy’s picture

Please be sure to re-enable stampede protection first.

deranga’s picture

Hi Jeremy,

Sent you some logs on email. Please let me know if there is any other information I can offer.

Many thanks,
Lee

Arvi89’s picture

Hi, I have also a big performance issue just after I updated, the MySQL server is much more used than before. Removing stampede protection seems to do the trick too.

I'll see if I can have some logs too, but not during the day as it slows the website a lot.

jeremy’s picture

@deranga, thanks for the debug info. The answer is not immediately jumping out at me, but looking at the release node () for related issues to see where this regression may have come from:

  1. What PECL extension are you using? (Memcache or Memcached?) #2376391: Call to undefined function lock_acquire() was related to PECL Memcached and Stampede Protection. That said, I don't see any obvious way this is going to cause a regression.
  2. Perhaps this regression is from the bug fix in #2413663: Notice: Undefined index: httprl lock_release memcache -- specifically, in earlier releases we could have freed locks that another process originally grabbed (defeating the purpose of the lock), see the fix here: http://cgit.drupalcode.org/memcache/commit/?id=06e9348 -- as you're only seeing this problem on one specific page, this seems a likely cause.
  3. Perhaps you've got some large items being stored/retrieved correctly now after #2415109: Notice: unserialize(): Error at offset 0 of 2527853 bytes in _dmemcache_get_pieces() (line 329 of modules/memcache/dmemcache.inc). -- we log when we split the item apart and store it, but we don't log each time we retrieve it from the cache. That said, we add "_multi" to the key name, and grepping through the log you provided I'm not seeing any keys with multi in the name.

From the above list, I think #2 is most likely the issue. Going back to your log, this does look suspicious (I've truncated the key names for clarity and to avoid leaking anything that shouldn't be public):

1489533542|add|semaphore|...cache_page|1
1489533554|get|semaphore|...cache_page|1
1489533554|delete|semaphore|...cache_page|1

This page is being rebuilt for 12 seconds -- is this expected?

And again, only 4 seconds later, this time taking 13 seconds:

1489533558|add|semaphore|...cache_page|1
1489533565|get|semaphore|...cache_page|1
1489533565|delete|semaphore|...cache_page|1

And again, only 6 seconds after that, this time taking only 7 seconds:

1489533571|add|semaphore|...cache_page|1
1489533578|get|semaphore|...cache_page|1
1489533578|delete|semaphore|...cache_page|1

And finally 5 seconds later, taking 12 seconds again:

1489533583|add|semaphore|...cache_page|1
1489533595|get|semaphore|...cache_page|1
1489533595|delete|semaphore|...cache_page|1

Why is this specific page-cache getting flushed / being rebuilt so often? Is this expected? Also, why is it taking so long to rebuild the page? (It looks like there's a lot of Views stuff happening on that page ...)

If the stampede protection is negatively impacting this page, you could explore adding to $conf['memcache_stampede_protection_ignore'] to avoid locking on these paths.

deranga’s picture

@Jeremy, thanks!

On point 1; Since this update went out, I've switched between pecl-memcache and pecl-memcached and this does not affect the performance.

For point 2; unfortunately its not just affecting this page; issue was reported by site admins but not with enough information of what pages they were accessing at the time, suggestion was that it was occurring for editing/adding node content. This was a page I could use as an example and quickly get repeatable results before rolling back or disabling the stampede protection so as not to adversely affect the end user.

And for 3 it sounds like you are ruling that out?

This issue with the updated module only occurs on the system when it is under live load, in our other environments I can't replicate the issue - possibly could if I were to write some jmeter tests to model our live load.

Now I have stampede turned off I wonder if it would make sense to log again and see if the log is distinctly different and might provide some clues?

The only way I can think to categorically assess this, is generate the jmeter tests so that in a non live env I can debug, without that and only a small amount of knowledge about drupal's caching layer, I'm not sure what next steps I can take; any suggestions?

Related to your notes on the log:

In that log, the page was reloaded several times by me (and possibly other anon users).

The non-cached build time for this page sits around 5-6 secs

With regards to cache being rebuilt, I'm not clear on that, and I can't think of anything we have in place that would trigger that; based on below TL;DR and times taken to build page with the new module version I'm wondering whether the issue is related to field api caching / a lock applied during the build of the form? Its almost as though it never actually caches the attached form fields --> I'll do some more digging into this...

TL;DR

The reason for slow page build time is owing to the field_attach_form()->_field_invoke_default->_field_invoke() of the user_register_form(), although there are only several fields on the register form all fields for the entity are attached via this method. I have not dug far enough to see if there is a particular field it hangs on, or if its just owing to the 30+ fields associated to the user profile.

The comment about views is interesting, I've done a little digging there, and it seems some old config for views was attempting to display them on a page that didn't require them, however this doesn't really affect the page load time.

I'll post that tiny patch adding in !page=>request_uri() in a new issue later this week.

jeremy’s picture

Perhaps temporarily try adding the page_cache to memcache_stampede_protection_ignore -- whether the problem does or does not go away will be an interesting datapoint. (I'd recommending cutting and pasting the entire example from README.txt into your settings.php, and then adding the page_cache table -- otherwise you could create new problems by removing other tables/keys from the ignore variable.

Doing a egrep "add|delete" on your log file, the page cache looks to me to be the only lock that's consistently being held a long time. That said, while that's being held, there's also a number of lock that look something like "MemcacheKeyPrefix-semaphorememcache_ctools_export%3Aviews_view%3ASearch%3Acache_views also being grabbed and held. If the test of disabling for page_cache doesn't work, perhaps re-enable, then try with cache_views.

Beyond that, I do see a lengthy lock held on cache_metatag once, but not consistently. (It holds it for 1-12 seconds in the log sample I have).

jeremy’s picture

@deranga any updates?

jeremy’s picture

Status: Active » Postponed (maintainer needs more info)

I am unable to duplicate this problem -- blocked until I get more information. Updating status.

deranga’s picture

Hi @Jeremy, not had chance to get back to this yet, as temporary solution to disable `stampede protection` has alleviated the immediate issue.

As soon as I get chance, I'll provide some more info.

jeremy’s picture

Thanks for the update!

There's now >5,000 users of this release ( https://www.drupal.org/project/usage/memcache ) and we're not seeing a surge of performance complaints, so currently I suspect there's something specific with your codebase or configuration. But, we'll see! :)

jstoller’s picture

Yesterday I pushed out an update that included Memcache 7.x-1.6 and my server load has been going crazy ever since. Right now this module is the prime culprit. What do you need to know?

jeremy’s picture

Did you try #2 above, and see if it helps? Maybe work through the suggestions already in the ticket if your symptoms are the same? Otherwise open a new ticket and describe your symptoms.

jstoller’s picture

When I updated the site on Monday, the server went down almost immediately, prompting 502 Bad Gateway errors. We rebooted and it it came back, but over the following 24 hours or so, anytime we had even moderate traffic CPU and memory usage would spike, making the server unresponsive. This was happening every few minutes Tuesday morning. It seemed like much of this was due to communication between Apache and the memcache server. Tuesday afternoon I set $conf['memcache_stampede_protection'] = FALSE; and it seemed to calm everything down. Then we had a couple people report Bad Gateway errors yesterday, so out of an abundance of caution I rolled back to memcache-7.x-1.5.

I didn't setup the server and I don't manage it, so my familiarity with the configuration is minimal, but here's what I can tell you... We're running:

  • Drupal 7.54 (it's a single codebase. No multisite)
  • Ubuntu 14.04.5 LTS
  • PHP 5.5.9-1ubuntu4.21
  • MySQL 5.5.54-0ubuntu0.14.04.1
  • Memcache v3.0.8 PECL extension
  • Memcached v1.4.14

The relevant Drupal settings I found are:

$conf['cache_backends'][] = 'sites/all/modules/contrib/memcache/memcache.inc';
$conf['cache_default_class'] = 'MemCacheDrupal';
$conf['cache_class_cache_form'] = 'DrupalDatabaseCache';
$conf['page_cache_without_database'] = TRUE;
$conf['page_cache_invoke_hooks'] = FALSE;
$conf['memcache_servers'] = array(
  '192.168.201.220:11211' => 'default',
);
$conf['memcache_bins'] = array(
  'cache' => 'default',
);
jeremy’s picture

Unfortunately there's not a lot to go on. Perhaps try collecting debug, as described in #4 above? It would also be good to confirm definitively that disabling does or does not solve the problem for you.

jeremy’s picture

Status: Postponed (maintainer needs more info) » Closed (cannot reproduce)

Old ticket, no updates in >3 years, closing