Support for Drupal 7 is ending on 5 January 2025—it’s time to migrate to Drupal 10! Learn about the many benefits of Drupal 10 and find migration tools in our resource center.When I enable memcached for caching the field cache stops working. I can reproduce this consistently. If I turn on the devel query log I see field_data_field_* queries for every field in the node:
SELECT t.* FROM field_data_field_long_text_sum t WHERE (entity_type = :db_condition_placeholder_0) AND (entity_id IN (:db_condition_placeholder_1)) AND (language IN (:db_condition_placeholder_2)) AND (deleted = :db_condition_placeholder_3) ORDER BY delta ASC
In the memcache admin log I see the following:
| Operation | Bin | Key | Hit |
|---|---|---|---|
| get | cache_field | drupal7-cache_field-field_info_fields | 1 |
| get | cache_field | drupal7-cache_field-field_info_types%3Aen | 1 |
| getMulti | cache_field | drupal7-cache_field-.wildcard- | 1 |
| getMulti | cache_field | drupal7-cache_field-.wildcard-field_info_fields | 0 |
| getMulti | cache_field | drupal7-cache_field-field%3Anode%3A5000 | 1 |
| getMulti | cache_field | drupal7-cache_field-.wildcard-field%3Anode%3A5000 | 0 |
| getMulti | cache_field | drupal7-cache_field-.wildcard-field_info_types%3A | 0 |
| getMulti | cache_field | drupal7-cache_field-field%3Ataxonomy_term%3A762 | 1 |
| getMulti | cache_field | drupal7-cache_field-.wildcard-field%3Ataxonomy_te | 0 |
| set | cache_field | drupal7-cache_field-field%3Anode%3A5000 | |
| set | cache_field | drupal7-cache_field-field%3Ataxonomy_term%3A762 |
I ran a simple test to see if memcache is working and it seems to be; I successfully set and returned a value in the cache_field bin.
For the time being I'm running a pretty simple setup, no bins or clusters. This is what I have in my settings.php
$conf['cache_backends'][] = 'sites/all/modules/memcache/memcache.inc';
$conf['cache_default_class'] = 'MemCacheDrupal';
$conf['memcache_key_prefix'] = 'drupal7';
Like I said, memcache seems to work OK. There are hits shown in the table above and I can successfully set and get a simple string.
I've also tried both the memcache (2.2.6) & memcached (1.0.2) PECL extensions with the same result. I'm running PHP 5.2.17 with a default Drupal install (only memcache and devel are enabled, beyond the standard installed modules).
This is a pretty significant performance issue. I ran a load test by loading the same 500 nodes through both node_load() and node_load_multiple(). Here are the results:
| PATH | MB MEMORY (MAX) | MB MEMORY (AVG) | Page Load MS | QUERY COUNT |
|---|---|---|---|---|
| node_load() Memcache | 88.25 | 76.06 | 6,967.00 | 11017 |
| node_load() Database | 32.75 | 32.56 | 840.1 | 2051 |
| node_load_multiple() Memcache | 50.5 | 50.5 | 2,485.60 | 36 |
| node_load_multiple() Database | 42.5 | 30.31 | 266 | 41 |
In almost every category the memcache caching is significantly worse than the DB. The only place it's better is the amount of queries when using node_load_multiple() because the other cache bins seem to work.
I can't see running this on a production site considering the above results.
Any suggestions?
Comments
Comment #1
pillarsdotnet CreditAttribution: pillarsdotnet commentedI loaded xhprof to chase this bug down. The big difference appears to be within the node_tag_new function, which updates the 'last viewed' timestamp of the specified node for the current user.
I can't imagine why that code would be so much slower with memcache turned on, but after several re-loads of the same page to prime the cache, the timings are as follows:
(µseconds)
Drilling down on the call graph, I see this further anomaly:
(µseconds)
The actual query is identical in both cases, except of course for the timestamp:
Comment #2
pillarsdotnet CreditAttribution: pillarsdotnet commentedCross-posting for support.
Comment #3
pillarsdotnet CreditAttribution: pillarsdotnet commentedWell, that was easy. I just dumped the history table and changed "Engine=InnoDB" to "Engine=MEMORY" and reloaded it. Problem solved, and *NOW* I know what was causing my database access to be 51% write, 49% read.
Comment #4
pillarsdotnet CreditAttribution: pillarsdotnet commentedPer discussion in IRC it is possible that the delay is caused by the PDO::commit() waiting for another transaction. Changing the engine on the history table to anything not supporting transactions would therefore solve this problem.
I'd need to do more testing to determine exactly what transaction is held open longer with MemCacheDrupal than with DrupalDatabaseCache.
Moving back to MemCache...
Comment #5
pillarsdotnet CreditAttribution: pillarsdotnet commentedTitle change.
Comment #6
catchSELECT FOR UPDATE could locks the row from being selected in some circumstances. See #910010: Potential race condition on variable_set() due to merge query implementation for some discussion.
Please take a look at that issue and see if it describes your problem. Were you doing this profiling while real traffic was hitting the server? If you were, it's possible that memcache freed up MySQL to the point where this became a bottleneck - then because you were able to handle the additional writes it hit this locking, then slowed the application down overall. However this is just conjecture at the moment.
Comment #7
BerdirNot sure why the focus of this issue seems to have changed completely, but the originally reported bug is now fixed and was related to a bug in getMulti(), which was completely broken.
And since nothing has happened here for many month, I'm marking this as fixed, feel free to re-open.