Cache stampede protection: drupal_render() and page cache

This looks great to me. I have a D6 site which slows to a crawl whenever content is posted, locking framework is designed just for cases like this. My only concern is it'd be nice if lock_wait() checked for the lock release at granularity less than a second (say 100ms), but that's not for this patch to deal with.

Looked at this again, there's nothing not to like here, RTBC.

+++ includes/bootstrap.inc
@@ -2076,7 +2076,20 @@ function _drupal_bootstrap_page_cache() {
+        // Some other request is building cache. Wait, then re-run this function.
+         drupal_add_http_header('X-Drupal-Cache', 'WAIT');

Do we need the header call for WAIT? Indented one too many places.

Additionally the lock name isn't per page? Locking all page cache generation across the site seems not ideal to me, we have the requested path by this point already.

Powered by Dreditor.

Looks great. Fine with keeping WAIT. Just waiting for testbot now.

Any idea how we can test the performance impact and correctness of this patch?

This is scary, very very scary. Compared to where this lock framework was used (=menu rebuild) this is a very very frequent operation. I have no idea where are we with deadlocks and in general, how large is the lock overhead. Anyone has an insight?

Lock waiting has very little overhead. The overhead I'd be more concerned about would be in http://api.drupal.org/api/function/lock_acquire/7

However - with database caching, cache_set() can be very expensive, let alone building the cached data, so there's trade off on stability. Since lock.inc is pluggable, it ought to be possible to reduce the lock_acquire() and lock_wait() overhead to pretty much nothing, at which point you have the protection against the site going down (which is a very real risk at the moment), without any performance impact.

I will see if I get a basic test case up with ab at some point to verify some of the above.

OK here's a test case:

1. Enable page caching for anonymous users.
2. apply attached patch to cache.inc - just log that we wrote to cache.
3. truncate cache_page
4. ab -c5 -n50

without locking:

cache_page
cache_page
cache_page
cache_page
cache_page

with locking:

cache_page

So, the locking works.

Then, to test performance impact, I did the following:

1. ab -c1 -n50 http://d7.7 (acquired lock but we didn't need the stampede protection - this would be the worst case from a performance standpoint)

HEAD:

Concurrency Level:      1
Time taken for tests:   0.557 seconds
Complete requests:      50
Failed requests:        0
Write errors:           0
Total transferred:      346351 bytes
HTML transferred:       322200 bytes
Requests per second:    89.76 [#/sec] (mean)
Time per request:       11.141 [ms] (mean)
Time per request:       11.141 [ms] (mean, across all concurrent requests)
Transfer rate:          607.19 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:     7   11  22.1      8     164
Waiting:        7   11  22.0      7     163
Total:          7   11  22.1      8     164

Patch:

Concurrency Level:      1
Time taken for tests:   0.402 seconds
Complete requests:      50
Failed requests:        0
Write errors:           0
Total transferred:      346351 bytes
HTML transferred:       322200 bytes
Requests per second:    124.27 [#/sec] (mean)
Time per request:       8.047 [ms] (mean)
Time per request:       8.047 [ms] (mean, across all concurrent requests)
Transfer rate:          840.63 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:     5    8  20.2      5     148
Waiting:        4    8  20.1      5     147
Total:          5    8  20.2      5     148

In this case the patched version was faster, so there's no measurable impact from acquiring the lock then not using it. A better test case would hit a higher spread of paths but still with a high cache hit rate, but this is fine from a sanity check standpoint.

2. ab -c5 -n50 (stamped protection kicks in)

HEAD:

Concurrency Level:      5
Time taken for tests:   0.403 seconds
Complete requests:      50
Failed requests:        0
Write errors:           0
Total transferred:      346355 bytes
HTML transferred:       322200 bytes
Requests per second:    124.13 [#/sec] (mean)
Time per request:       40.282 [ms] (mean)
Time per request:       8.056 [ms] (mean, across all concurrent requests)
Transfer rate:          839.68 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    1   4.6      0      17
Processing:     5   39  94.3      7     386
Waiting:        5   38  93.6      7     385
Total:          5   40  98.7      7     403

Percentage of the requests served within a certain time (ms)
  50%      7
  66%     10
  75%     12
  80%     15
  90%    216
  95%    346
  98%    403
  99%    403
 100%    403 (longest request)

Patch:

Concurrency Level:      5
Time taken for tests:   1.050 seconds
Complete requests:      50
Failed requests:        0
Write errors:           0
Total transferred:      346351 bytes
HTML transferred:       322200 bytes
Requests per second:    47.62 [#/sec] (mean)
Time per request:       104.991 [ms] (mean)
Time per request:       20.998 [ms] (mean, across all concurrent requests)
Transfer rate:          322.15 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    2   6.3      0      24
Processing:     5   90 277.7      6    1030
Waiting:        5   90 277.3      6    1026
Total:          5   92 284.0      6    1050

Percentage of the requests served within a certain time (ms)
  50%      6
  66%      7
  75%      7
  80%      7
  90%    152
  95%   1042
  98%   1050
  99%   1050
 100%   1050 (longest request)

As you can see, in the latter example, we lose requests per second, but that's not the interesting thing.

Without the patch, there are these long requests:

  90%    216
  95%    346
  98%    403
  99%    403

Each of those is a full page build and cache_set() - which takes about 200-400ms, of which all the time is spent generating the content and writing to cache. Note this was on HEAD with only one node on the front page.

With the patch, we instead get

 90%    152
  95%   1042
  98%   1050
  99%   1050
 100%   1050 

in this case, the 152ms request builds the content and write to cache, the other 4 requests sit around and do nothing for a second, and only 50ms is spent actually doing anything - sleep(1) uses 0 cpu for the second.

So, while raw performance is a little slower, the webserver has done 1/5th the work for four out of five cache misses. On a real site where a page cache miss might mean 1s to build and write the cache, we'd see no speed impact either.

It's also possible, especially with a non-SQL lock.inc, but even with it, to make lock_wait() more granular - see #802856: Make lock_wait() wait less - removing wait times for users who are put into the holding pattern on the cache miss. With both patches applied, I ran the same ab.

Concurrency Level:      5
Time taken for tests:   0.363 seconds
Complete requests:      50
Failed requests:        0
Write errors:           0
Total transferred:      346351 bytes
HTML transferred:       322200 bytes
Requests per second:    137.56 [#/sec] (mean)
Time per request:       36.347 [ms] (mean)
Time per request:       7.269 [ms] (mean, across all concurrent requests)
Transfer rate:          930.56 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    1   4.9      0      20
Processing:     5   34  63.8     11     240
Waiting:        5   33  62.7     10     231
Total:          5   36  67.9     11     247

Percentage of the requests served within a certain time (ms)
  50%     11
  66%     16
  75%     22
  80%     24
  90%    198
  95%    240
  98%    247
  99%    247
 100%    247 (longest request)

This time, the longest request is twice as fast as without the patch - there's no contention for either CPU or database writes on building the cache, and once the lock is released, requests which are made to wait still get from cache and return the page far within the time which would have otherwise been spent building and writing to cache themselves. We might want to leave that more aggressive lock_wait() to a pluggable include, but it shows that this approach can both improve overall stability and have zero raw performance cost in terms of user experience.

Forgot to attach the hack to cache.inc - this includes both patches as well.

I asked others to do research into lock.inc which was answered that my request is FUD. lock_acquire does a database write. That's not much of an overhead, but it's there. However, it's pluggable, so be it.

There can be no deadlock as far as I can see.

What IS possible, however, that you recurse so many times that PHP dies out. We need a recurse protection in there.

Edit: that's only necessary if catch decimates the wait time. If he raises $delay = 30 to $delay = 300 changing the behaviour to the same just more fine grained, then such a protection is not needed.

OK, so let's go with it in the hopes the other patch gets in too.

To go along with catch's ab benchmark.

I made it so Drupal clears the cache for every other page request, so I get a HIT/MISS scenario. I couldn't get it to do a WAIT no matter how much I bombarded it. I'm sure it works though, just couldn't get the right conditions for it to fire.

Locking stuff average (MISS): 0.0143499279022158
Other stuff inside (WHEN CACHE MISS) _drupal_bootstrap_page_cache() average: 0.1099051904678

Minimum lock stuff time: 0.00162601470947
Minimum other stuff time: 0.0664360523224

Maximum lock stuff time: 0.150331020355
Maximum other stuff time: 0.228527784348

"Locking stuff average (MISS)" means elapsed time from comment "// Cache miss. Avoid a stampede." to the point it sets the header to "X-Drupal-Cache: MISS".

"Other stuff inside (WHEN CACHE MISS) _drupal_bootstrap_page_cache()" means elapsed time from beginning of function to the point it sets the header to "X-Drupal-Cache: MISS".

Conclusion is that it looks like the locking stuff takes very little time compared to the rest of function. No opcode cachers being used btw.

Arggg I messed up somewhere writing this down.. I'll have to correct these times.

Ok those times should be right now. I've got a perl app that makes 100 page requests to Drupal, half of them (when they miss) insert those elapsed times into the header. I've run it several times and they're pretty consistent.

Just out of curiosity... you have fully researched distributed lock management here? Is the "lock system" being referred to a "distributed lock manager"?

If you have a cache shared across a number of distinct processors - a web server farm - then you will need this level of synchronisation I think. There are all sorts of interesting race conditions and failure modes that need to be considered.

This is not easy. I had discussions with some of the VMS developers who did the first ever DLM and it took this amazing development team quite a few iterations to get it right.

cheers

PHP is single threaded - one process can only ever request or secure a lock on one thing at a time, so the only situation where you could have a deadlock is where a lock is acquired then the process dies with a fatal error before releasing the lock - in that case the lock will expire and be released eventually. If there are other potential race conditions in the locking framework, then those deserve separate issues against lock.inc. The original issue is here #251792: Implement a locking framework for long operations.

@dhthwy - to get a WAIT, you'll need to run your perl script in two processes (or just use ab which handles that for you).

@catch

This applies to PHP running on seperate servers where the database is shared between the servers?

catch, I ran a bunch of perl procs. Still couldn't get it.. hehe. Maybe ab+perl. I did it in perl so I could get the header stuff I injected from Drupal.
But not worth me trying for anyway since you've already tested that and the locking doesn't appear to have a noticable impact on performance.

Instead of locking and waiting, I'd prefer to come up with a write-through cache. In such scenario, other requests continue to use the old data until it was replaced in the cache. That requires zero waiting from other requests. Have we considered that?

Re: the polling delay question: the standard, database-based, lock.inc implementation is nothing more then a cheap baseline. There are several ways to do that better, without polling, even with a database-based implementation, but that requires some additional privileges (locking, etc.) that most shared hostings cannot provide.

The best way to avoid replacing a cache stampede by a lock stampede would probably be to implement decay polling in lock.inc by default.

This said, let's study how much it takes to implement a semi-write-through strategy. (complete write-though is not possible, because there are a lot of cases where the data itself has completely disappeared, and we have to lock in that case anyway)

This is for absolute cache misses - whenever cache_get() returns FALSE, not for when there is existing, stale, data in the cache which needs to be updated. They're two different issues.

At the moment core's cache.inc returns false for the update case too - so this patch would stop a stampede in that case, but with a write-through, you'd have cache_get() return TRUE - so this is entirely compatible with that if we added it in a separate patch.

For reference:

http://tag1consulting.com/patches/pagecache_lock
http://groups.drupal.org/node/59318
http://drupal.org/node/295738

These deal with stale cached data, but not empty data, if we could get that into core too it'd be great, but it's doesn't solve all cases.

Cross posted, I still think this belongs where it is, and write-through belongs in cache.inc, so leaving at CNR rather than CNW.

In here, let's at the minimum implement decay polling in lock.inc.

There's a D6 patch for write through on #762978: Prevent cache stamped for page cache table, I just bumped that issue to D7.

Here's the same patch with decay polling, I didn't change the minimum wait from 1s, that should stay in a separate issue.

Brain no worky. Less broken patch.

Minus one more stupid error, and with some improvements to the lock.inc change via Damien in irc.

@lostchord

Being an old VMS internals guy...

We are not talking about DLM in this patch. The locking is being done by inserting a row in the database, not by the webservers on many different nodes. If your database is clustered, then it is up to the database to worry about the locking required to make transactions work correctly.

In VMS I didn't care about DLM as long as $ENQ/$DEQ calls worked the same on single node or in a cluster.

@jriedel

Ditto the old VMS internals bit... I'm much happier in VAX assembler and a relative newbie to PHP :-) I think the critical part in your reply is this:

If your database is clustered, then it is up to the database to worry about the locking required to make transactions work correctly.

I suspect this will probably not be the case in most 'simple' replication scenarios.

I'm assuming that as far as locking is concerned we are dealing with this part of the API and the intent is to provide a mutex capability rather than a generalised resource synchronisation capability. In this context I've got a couple of questions:

• Would it be true to say that if I'm sharing tables between sites using common prefixes then the semaphore table would have to be shared as well? (Actually I've just noticed that this form of sharing seems to have been discouraged as of March 4th...that was an attractive feature).
• The integrity of the system relies on independent module developers choosing non-conflicting lock names. Wouldn't it be better to force modules to register lock names and detect conflicts before they potentially cause trouble?

I have some other questions regarding how the lock_* stuff behaves but I'll dump those in a seperate post when I've dug a bit more. Finding API documentation and code is relatively easy, finding out what the code was actually intended to do (as opposed to what you can see that its doing), the requirements it's based on, is proving a lot harder.

cheers

+++ includes/bootstrap.inc	20 May 2010 12:21:53 -0000
@@ -2076,7 +2076,20 @@ function _drupal_bootstrap_page_cache() 
+        // Some other request is building cache. Wait, then re-run this function.

Is 'building cache' proper English?

+++ includes/bootstrap.inc	20 May 2010 12:21:53 -0000
@@ -2076,7 +2076,20 @@ function _drupal_bootstrap_page_cache() 
+        return _drupal_bootstrap_page_cache();

Why do we have to call this function recursively? That seems odd given that we might execute SQL queries and whatnot. For example, the IP blocking code would be executed twice.

It looks like the lock protection should go in drupal_page_get_cache() rather than here. Moshe, any reason not to do that?

I'm wondering if instead of recursion we could just do a while (lock_wait()); will try to roll a patch for that tomorrow. If for some reason doesn't work out this is RTBC.

I had a look at the while() loop but it was more verbose than recursion (iirc, can't believe I left this hanging for a week, sorry :( ). Since the recursion is otherwise completely harmless, and only happens on a cache miss that's failed to acquire a lock anyway, marking this back to RTBC.

lock_initialize() moved to _drupal_bootstrap_variables(), removed the call from the patch, no other changes.

beejeebus noticed a very nasty typo in irc. No function is called _drupal_page_get_cache().

Why does this add the lock initialization back in? That's done in _drupal_bootstrap_variables() now so shouldn't be necessary to repeat.

Well except in the case where you set $conf['page_cache_without_database'] = TRUE, then variable_initialize() gets skipped...

Back to RTBC again.

+++ includes/bootstrap.inc	13 Jul 2010 07:13:37 -0000
@@ -870,11 +870,35 @@ function drupal_page_get_cache($check_on
+    // the database, drupal_page_get_cache() could get called before the lock ¶

+++ includes/common.inc	13 Jul 2010 07:13:40 -0000
@@ -5235,7 +5236,17 @@ function drupal_render_cache_get($elemen
+  ¶

Trailing white-space.

+++ includes/bootstrap.inc	13 Jul 2010 07:13:37 -0000
@@ -2127,23 +2155,18 @@ function _drupal_bootstrap_page_cache() 
+      // If the skipping of bootstrap hooks is not enforced, call hook_boot.
...
+      // If the skipping of bootstrap hooks is not enforced, call hook_exit.

Function names should have trailing ().

Powered by Dreditor.

#60: render.lock_.patch queued for re-testing.

Comment issues were already in HEAD, but cleaned up anyway.

+ // Try to get either the cached page or a lock five times. If that fails,
+ // continue with page execution, because the site may still be able to
+ // serve the request.

I do not understand the use of this loop:

• It's the job of lock_wait() to loop (and it already does)
• The default $delay of lock_wait() is 30s, so this patch would make Drupal wait for up to 150s before proceeding to non-cached page rendering (!!!!)

Something as simple as:

$cache = cache_get($base_root . request_uri(), 'cache_page');
if (!$cache && !$lock_acquired = lock_acquire($name)) {
  lock_wait($name, 2);
  $cache = cache_get($base_root . request_uri(), 'cache_page');
  if (!$cache) {
    $lock_acquired = lock_acquire($name);
  }
}

Feels more then enough.

Sounds like this still needs discussion based on Damien's last comment.

I'd want more than 2 seconds for a wait, Drupal.org itself used to take around 30 seconds to load /tracker. However no loop seems fine here.

Looks fine to me. lock_wait() bails out as soon as possible anyway, so I don't see a reason to set anything but the default there.

lock_wait() exits as soon as it can anyway, I don't see any reason to specify 5 seconds. If I render cache something that takes 15 seconds to build (a huge page callback, someone changes a 2 second view to a 20 second one by adding an extra sort on it, a block on every page that has to make a load of network requests to a slow third party service, plenty of possibilities), then that's precisely what this patch should add a little bit of protection against.

Subscribing. Test failure is odd.

It seems that #79 makes "Forum functionality (ForumTestCase)" timeout. The failure seems legit.

Yeah, a timeout is likely. The PIFR bot can't distinguish infinite loops from other errors yet. Usually it's reported as a fatal error, but here we're getting run-tests.sh error. In any case, the forum tests may have some clues.

#886152: All fields are hidden after the administrator newly configures a view mode to not use 'default' display landed

@justinrandell, when you ran run-tests.sh, what concurrency did you set? I have a feeling the tests only fail when a higher concurrency is set (the production test bots have concurrency 4+, I think). Concurrency would probably trigger lock_wait(), etc. so that might be the key to reproducing the failure.

I've only skimmed through the code in the patch, but I am interested in what changed between #72 and #79 to cause the failure (interdiff please?). Either HEAD broke the patch, or #79 added something that broke it. Hmm.

Also, I'm interested in a unit test being written for this (read #12 - #13, yes it's difficult, but I think we should try). For the reasons that this touches critical bootstrap code in a major way, and secondly to debug the run-tests.sh failure, which if it is due to concurrency, would point to a legitimate bug.

Well, actually run-tests.sh concurrency in theory shouldn't trigger lock_wait(), since each test method gets its own database, and its own set of locks.

And although lock.inc has some rudimentary tests in core, apparently there is no way to actually test concurrent requests with our framework. Maybe we'll need some thinking out-of-the-box on this one.

Wow! Now we can isolate the change that causes failure.

interdiff lock.802446.72.patch lock_13.patch 
diff -u includes/common.inc includes/common.inc
--- includes/common.inc	29 Oct 2010 03:16:31 -0000
+++ includes/common.inc	28 Oct 2010 23:23:55 -0000
@@ -5574,10 +5574,10 @@
   }
   $bin = isset($elements['#cache']['bin']) ? $elements['#cache']['bin'] : 'cache';
 
-  if (!$cache = cache_get($cid, $bin) && !lock_acquire($cid, 5)) {
-    lock_wait($cid, 5);
+  if (!$cache = cache_get($cid, $bin) && !lock_acquire($cid)) {
+    lock_wait($cid);
     if (!$cache = cache_get($cid, $bin)) {
-      lock_acquire($cid, 5);
+      lock_acquire($cid);
     }
   }

Looks like the only change is using '5' as the timeout/delay. Interesting.

I think this is the problem:

The lock is supposed to be released in http://api.drupal.org/api/function/drupal_page_footer/7 (via drupal_page_set_cache(), etc), but it's possible that in some cases, that code is not running and the lock is not properly released. In that case, with the timeout being 30 (default), PHP times out waiting for a lock that was never released properly. It might be that we need to call lock_release() in a shutdown function to ensure that it is called whenever exit() is called, to catch cases like drupal_goto().

OK, taking http://api.drupal.org/api/function/lock_release_all/7 into consideration, all locks should be released on shutdown. Nevertheless, it appears that our lock is not being released. There's some bug here that we don't grok yet.

Another perplexing part is that PHP is not supposed to time out due to sleeping! (on Linux anyway). It still seems like there is a direct correlation between the lock_wait() timeout being 30 seconds in the failed patch, and PHP having a global (default) timeout of 30. The passing patch uses 5 as lock_wait() timeout, and I think it's safe to say that it's using the full 5 seconds and continuing silently.

Created #956948: Locking framework ungrokably fails testing to investigate test failures.

Facepalm.

header('Content-Type: text/plain; charset=utf-8');

function foo() {
  return FALSE;
}

function bar() {
  return TRUE;
}

if ($cache = foo() && bar()) {
  print "A is wrong!\n";
}

if (!$cache = foo() && !bar()) {
  print "B is wrong!\n";
}

if (!($cache = foo()) && !bar()) {
  print "C is wrong!\n";
}

Output:

B is wrong!

@chx, can we get a phpwtf on this?

Attached patch is #93 with proper parentheses.

interdiff lock_13.patch facepalm.patch 
diff -u includes/bootstrap.inc includes/bootstrap.inc
--- includes/bootstrap.inc	28 Oct 2010 23:23:51 -0000
+++ includes/bootstrap.inc	28 Oct 2010 23:23:51 -0000
@@ -869,7 +869,7 @@
     }
 
     $cid = $base_root . request_uri();
-    if (!$cache = cache_get($cid, 'cache_page') && !lock_acquire($cid)) {
+    if (!($cache = cache_get($cid, 'cache_page')) && !lock_acquire($cid)) {
       lock_wait($cid);
       if (!$cache = cache_get($cid, 'cache_page')) {
         if (lock_acquire($cid)) {
diff -u includes/common.inc includes/common.inc
--- includes/common.inc	28 Oct 2010 23:23:55 -0000
+++ includes/common.inc	28 Oct 2010 23:23:55 -0000
@@ -5574,7 +5574,7 @@
   }
   $bin = isset($elements['#cache']['bin']) ? $elements['#cache']['bin'] : 'cache';
 
-  if (!$cache = cache_get($cid, $bin) && !lock_acquire($cid)) {
+  if (!($cache = cache_get($cid, $bin)) && !lock_acquire($cid)) {
     lock_wait($cid);
     if (!$cache = cache_get($cid, $bin)) {
       lock_acquire($cid);

ignore this one

Basic boolean logic.

+++ includes/bootstrap.inc
@@ -860,11 +860,29 @@ function drupal_page_get_cache($check_only = FALSE) {
+    if (!$cache = cache_get($cid, 'cache_page') && !lock_acquire($cid)) {
...
+      if (!$cache = cache_get($cid, 'cache_page')) {

+++ includes/common.inc
@@ -5573,7 +5574,14 @@ function drupal_render_cache_get($elements) {
+  if (!($cache = cache_get($cid, $bin)) && !lock_acquire($cid)) {
...
+    if (!($cache = cache_get($cid, $bin))) {

common.inc looks correct to me, bootstrap.inc not.

@Damien, did you see the patch in #107? #109 is incomplete, it doesn't fix

if (!$cache = cache_get($cid, 'cache_page') && !lock_acquire($cid)) {

I believe the patch in #107 is more complete.

And also,

if (!$cache = cache_get($cid, $bin)) {

is fine by itself, but #109 changes it. It's only when we add the && that problems happen with operator precedence, I actually prefer to leave out the paren's if it's a simple expression like above.

#109 was a crosspost. We just came to the same conclusion.

Oh oh. #107 vs. #109:

interdiff facepalm.patch 802446-lock-render-proper.patch
diff -u includes/bootstrap.inc includes/bootstrap.inc
--- includes/bootstrap.inc	28 Oct 2010 23:23:51 -0000
+++ includes/bootstrap.inc
@@ -869,7 +869,7 @@
     }
 
     $cid = $base_root . request_uri();
-    if (!($cache = cache_get($cid, 'cache_page')) && !lock_acquire($cid)) {
+    if (!$cache = cache_get($cid, 'cache_page') && !lock_acquire($cid)) {
       lock_wait($cid);
       if (!$cache = cache_get($cid, 'cache_page')) {
         if (lock_acquire($cid)) {
diff -u includes/common.inc includes/common.inc
--- includes/common.inc	28 Oct 2010 23:23:55 -0000
+++ includes/common.inc
@@ -5576,7 +5576,7 @@
 
   if (!($cache = cache_get($cid, $bin)) && !lock_acquire($cid)) {
     lock_wait($cid);
-    if (!$cache = cache_get($cid, $bin)) {
+    if (!($cache = cache_get($cid, $bin))) {
       lock_acquire($cid);
     }
   }

The only notable difference is that #107 fixes the page cache operator precedence. And then we get page cache test fails. This is exactly the opposite of what to expect: #107 should pass, #109 should fail!

Regardless, we have moved past the run-tests.sh error by fixing this operator bug. That is at least encouraging, but still, using timeout of 30 v.s 5 shouldn't cause the bot to crash like that. I'll try to expose the bug in #956948: Locking framework ungrokably fails testing (looks like the bot is caught in an infinite loop there).

header('Content-Type: text/plain; charset=utf-8');

function foo() {
  print "foo\n";
  return FALSE;
}

function bar() {
  print "bar\n";
  return TRUE;
}

print "testing B\n";
if (!$cache = foo() && !bar()) {
  print "B is wrong!\n";
}

print "testing C\n";
if (!($cache = foo()) && !bar()) {
  print "C is wrong!\n";
}

print "testing E\n";
if (!$cache = bar() && !bar()) {
  print "E is wrong!\n";
}

print "testing F\n";
if (!($cache = bar()) && !bar()) {
  print "F is wrong!\n";
}

testing B
foo
B is wrong!
testing C
foo
bar
testing E
bar
bar
E is wrong!
testing F
bar

This simple test shows that in #109 the page cache logic should be totally broken, and #107, which contains the paren's, should be correct. Yet the bot prefers #109. WTF is going on here? :P

In #956948: Locking framework ungrokably fails testing I've isolated the run-tests.sh failure to the operator precedence bug. We still need to figure out why page cache tests are failing in #107 though.

To fix the page cache tests, all I needed to do was move header('X-Drupal-Cache: MISS') out of the lock_acquire() block and to the bottom of the function. The header should get sent regardless of whether locking succeeded.

#116: 802446-116-lock-page-render-caches.patch queued for re-testing.

Hmm, more fallout from #808560: Node comment statistics are only partially exposed in node_load() and are missing last_comment_uid. Fortunately that was just fixed!

#116: 802446-116-lock-page-render-caches.patch queued for re-testing.

#116: 802446-116-lock-page-render-caches.patch queued for re-testing.

Still RTBC; test fails were not related.

#116: 802446-116-lock-page-render-caches.patch queued for re-testing.

I talked with @David Strauss today about this patch; he noted that when using varnish, page cache stampedes are already taken care of. That could cause some unnecessary locking, although Pressflow d7 may introduce an opt-out of core page caching ("External" cache mode), which would defer everything to varnish instead. Render cache stampede protection is still a nice improvement though.

There could be cases where fatal errors or uncaught exceptions leave the lock hanging for the duration (lock_release_all() doesn't run in that case). That's a tricky issue; in the case of fatals it's impossible to release the lock and it will just have to expire. In the case of exceptions, it might be possible to have a global try { } catch { release locks, re-throw exception }. That is another issue though. I think the current patch is OK to commit.

lock_release_all() happens in a shutdown function. I haven't personally tested it but I think others did at the time and this was pretty resilient to some deliberately triggered fatal errors.

Unless I'm mistaken, while varnish has a 'grace' setting which allows for stampede protection against expired entries, it doesn't have any protection against stampedes in a cold start situation (although maybe it's possible to do that with a custom vcl). So this is a slightly different issue. fwiw I think you can do roughly the equivalent to pressflow D6 external page caching with vanilla D7 already, see #627496: Document using a null cache for page caching with reverse proxies.

I tried to look at this tonight, but not only is it way over my head, it's also got Dries's fingerprints all over it. I do also get very nervous about sentences like "If we agree on this approach, I will submit similar patches for block and page caches (others?)." Tons of follow-up patches are not something we have time for at this point. But the trade-off might be worth it, dunno.

Leaving for The Spikey Haired One to make the call.

subscribing

#116: 802446-116-lock-page-render-caches.patch queued for re-testing.

#116: 802446-116-lock-page-render-caches.patch queued for re-testing.

Subscribing.

De-fuzzed again...

Subscribe.

Subscribe.

I keep thinking about this patch and have concerns about it now. These are similar to the concerns around the locking in variable_initialize(), and #802856: Make lock_wait() wait less is designed to deal with part of this, but I'm not sure if it's enough.

Say you have something that takes 300ms to build on a cache miss, and that is rendered on every page (for example a block in the footer).

Without locking, you'll get a cache stampede - every request does that 300ms of processing until one sets the cache (and all the ones that missed will try to write back to cache).

With locking, only one request tries to build the item, so you save the apache/database CPU time from that 300ms.

However between acquiring the lock and writing to cache you have a 300+ms window where every other process hitting the site has to wait.

If they start waiting right at the beginning of the cache miss, then the request will take 700ms longer than it would. If they start to wait right at the end, then it'll be 1300ms after the initial lock_acquire() before those requests are able to continue.

During this time CPU load on the server is going to be low (apart from lock_may_be_available() which is minimal), but it runs the risk of exceeding MaxClients - since you'll have all these sleeping processes waiting around. What we're effectively doing in those situations is adding a global read lock across the entire site (even with multiple webservers and database servers there'd still be a single read lock).

And the current patch would make this even more pronounced than the current variable patch, because the polling in lock_wait() doubles each time.

For now, I'm just removing the changes to lock_wait() from here, but I think we need to try to come up with a uniform approach to this if possible. For example we could lock cache writes but not reads, or we could lock_wait($name, 1); by default in these examples so there's less chance of stacking up apache processes, then go ahead and build the items anyway, while still not writing back to cache (or checking the cache before writing back to it).

But there are complex trade-offs here that need a bit more discussion.

Back to CNR.

I'm getting multiple errors like the following:

PHP Fatal error: Call to undefined function db_insert() in /var/www/includes/lock.inc on line 125

This happens in a call to lock_acquire() added by the patch in #139.

The problem is that if $config['page_cache_without_database'] is set, then drupal_page_get_cache() gets called before the database system has been initialized. The #139 patch loads lock.inc but does not load database.inc. Calling lock_acquire() therefore results in the above error.

The attached patch loads both database.inc and lock.inc IF:

• cache_get($cid, 'cache_page') returns FALSE,   AND
• variable_get('page_cache_without_database') returns TRUE

Should there should be a test that generates a page load of modified content with $conf['page_cache_without_database'] set? If so, should that test be in core?

Wow. Testbot is reporting failure to checkout the drupal repository. I wish someone with access to qa.drupal.org would update its status page when stuff like that happens.

I'd post a comment to the qa.drupal.org status page, but my account has apparently been banned from that server.

Fixed silly typo.

#143: cache_stampede-802446-143.patch queued for re-testing.

subscribe

Just a note that we added stampede protection for empty caches to the 6.x-1.x memcache backend in #962422: Empty cache stampede protection, this (as well as the 'grace' mode for expired items) is configurable in settings.php, disabled by default (since we want to ensure people use memcache-lock.inc with it). Patch needs to be ported to 7.x branch still.

I am starting to think that cache backends are a better place for this to live, and we should reserve locking in core for where there are actual consistency issues (such as menu_rebuild(), arguably variable caching). A lock_acquire() with memcache is extremely cheap, but this is not going to be the case with the SQL version we ship with, and the cost of that happens whether there is a stampede or not.

Not changing status, interested to see what other people think about this, but since I was a strong supporter of this patch originally wanted to confirm that I've changed my mind on it now. If custom/contrib code is building an extremly expensive item and wants to make sure that only one process tries to do this, then it makes sense to do it there - but for the render cache some things may be quite cheap, or unique to each page (even user) and not that likely to cause a stampede.

#143: cache_stampede-802446-143.patch queued for re-testing.

Adding backport tag, this is a task.

Tagging issues not yet using summary template.

@Moshe - well #147/memcache has generic stampede protection for all cache entries using the lock framework, so if it's simple enough at that level, it should be OK elsewhere.

I'm going to put this down to normal priority.

I like the idea of #lock => TRUE, tried to build something like that into DrupalCacheArray.

#143: cache_stampede-802446-143.patch queued for re-testing.

putting back lost tag for needs issue summary update (instructions)

Too bad this never got in ... Hopefully we can find a better (parallel) solution for D8 ...

E.g. placeholder data while waiting for the lock, then try later again ...

Unassigning stale issue. Hopefully someone else will pursue this.

I don't think this is in a state where it needs committer feedback (six years later) since the proposed resolution is not applicable for D8. It would need to be updated with a new proposal.

(Also we don't use "Needs committer feedback" anymore for D8 core since there are three distinct committer roles.)