Race conditions in CacheCollector/State (again)

Whenever I see a call to wait on a lock I get a chill up my spine.

I agree with this but I think we might not need the lock wait here, just to more aggressively clear/invalidate/set the cache even when we can't acquire the lock. Pushed a commit that tries this.

The lock name was a red herring but I discovered some real race conditions.

https://git.drupalcode.org/project/drupal/-/jobs/3827879 runs a frequently failing tests that depends on writing to state 2500 times and is green with the MR.

https://git.drupalcode.org/project/drupal/-/pipelines/380036 is a full test run with only nightwatch failures, which this won't help with.

I'm going to spend a bit more time trying to figure out if we can do away with holding the lock, if we can't, it should result in a better comment, possibly add a @todo and issue to have another try in a follow-up, if we can release the lock, then great we don't need to explain why we can't.

Alright it looks like that theory was correct.

The remaining race condition was something like as follows:

We lock cache writes, but not cache reads. CacheCollector uses the cache created timestamp (which is stored with millisecond precision) to detect if the cache item it read at the beginning of the request is the same as the one it reads again at the end of the request.

Because we only lock writes, it's possible for two processes to lock acquire, cache write, lock release within the same millisecond. For the usual CacheCollector case this is a non-issue, because we are generally caching things which are expensive to build and don't get written to as such (like the runtime theme registry), so all these things happening in a single millisecond does not really come up. It's a problem here because state is cheap to build and also gets individual keys written to, especially with the database on a ramdisk on the same server etc. like gitlab pipelines.

If State::set() writes a cache item in the same millisecond as another cache item is set, this breaks the race condition detection in ::updateCache(). Another request can read the newly outdated cache item, get to the end of the request, compare with the State::set() one, see them as 'the same' and then write back stale data.

Holding the lock longer was preventing the situation where another process writes back to the cache item immediately after State::set() has written to it, having read a different cache item created in the same millisecond as the call to State::set().

Instead of that, we can usleep() for 10 milliseconds before and after writing, and try a bit harder to acquire the lock, this still results in 2500 passes for the test, but it doesn't involve either the full lock->wait() call or holding the lock that were necessary in earlier iterations.

There are still other theoretical race conditions here - e.g. if two servers have a time offset, and write cache items in the 'same' millisecond even though they are actually different due to the offset. We could potentially protect against this in CacheCollector by hashing the cache data every time it's read, and then comparing the hash when we write back to the cache - but this would introduce hashing overhead to every cache collector read which is not great. Or maybe we could store the hash with the cache item and compare that, which would mean changing the cache data structure a bit, but that might work and allow us to remove the usleep() calls then.

Going to try that approach in the sandbox MR and see if it's straightforward enough.

OK trying to use a hash of the data doesn't work, or at least not yet, it also requires changing the structure of the cache item which means that even if did work it would probably be minor only.

I'll open a follow-up for that.

https://git.drupalcode.org/project/drupal/-/merge_requests/10704 is the MR and approach to review.

Restored the 2500 runs to its previous state before that diversion, to get a fresh green run on there.

https://git.drupalcode.org/project/drupal/-/jobs/3831420

Here's the follow-up: #3496328: Use a hash of the cache data for CacheCollector race condition detection.

Just kicked off a third run of https://git.drupalcode.org/project/drupal/-/merge_requests/10705/pipelines which will give us 7500 passing tests in a row assuming it also comes back green.

@spokje it's 2500 runs * 3, should be OK.

Well that's interesting, 2 runs out of 7500 failed https://git.drupalcode.org/project/drupal/-/jobs/3831692/viewer

Looks like this happened when the overall time for the test went up to 30-50+ seconds from 6-10s

Drupal\Tests\layout_builder\Functional\LayoutBuilderBlocksTe   1 passes    9s                                      
Drupal\Tests\layout_builder\Functional\LayoutBuilderBlocksTe   1 passes    9s                                      
Drupal\Tests\layout_builder\Functional\LayoutBuilderBlocksTe   1 passes    9s                                      
Drupal\Tests\layout_builder\Functional\LayoutBuilderBlocksTe   1 passes    9s                                      
Drupal\Tests\layout_builder\Functional\LayoutBuilderBlocksTe   1 passes    9s                                      
Drupal\Tests\layout_builder\Functional\LayoutBuilderBlocksTe   1 passes   18s                                      
Drupal\Tests\layout_builder\Functional\LayoutBuilderBlocksTe   1 passes   23s                                      
Drupal\Tests\layout_builder\Functional\LayoutBuilderBlocksTe   1 passes   24s                                      
Drupal\Tests\layout_builder\Functional\LayoutBuilderBlocksTe   1 passes   26s                                      
Drupal\Tests\layout_builder\Functional\LayoutBuilderBlocksTe   1 passes   26s                                      
Drupal\Tests\layout_builder\Functional\LayoutBuilderBlocksTe   1 passes   30s                                      
Drupal\Tests\layout_builder\Functional\LayoutBuilderBlocksTe   1 passes   36s                                      
Drupal\Tests\layout_builder\Functional\LayoutBuilderBlocksTe   1 passes   35s                                      
Drupal\Tests\layout_builder\Functional\LayoutBuilderBlocksTe   1 passes   35s                                      
\Drupal\Tests\layout_builder\Functional\LayoutBuilderBlocksT   0 passes   37s   1 fails                            
Drupal\Tests\layout_builder\Functional\LayoutBuilderBlocksTe   1 passes   44s                                      
\Drupal\Tests\layout_builder\Functional\LayoutBuilderBlocksT   0 passes   48s   1 fails                            
Drupal\Tests\layout_builder\Functional\LayoutBuilderBlocksTe   1 passes   62s                                      
Drupal\Tests\layout_builder\Functional\LayoutBuilderBlocksTe   1 passes   60s     

Might be a sign of the lock failing to be acquired or similar.

Don't think this necessarily invalidates the fix here since it's still a significant improvement, but might show we need to lock wait for longer and/or explore the hash idea further in the other issue.

Pass rate of 12248/12500 now.

Another 1/2500 fail on https://git.drupalcode.org/project/drupal/-/jobs/3832573/viewer so at 14997/15000 passes now.

Hmm four fails on https://git.drupalcode.org/project/drupal/-/jobs/3849058 out of 2500

Famous last words because we're down to 4/15000 odds so false negatives are increasingly likely, but might have figured out the last race condition.

In earlier iterations of the MR, I was holding the lock acquired in State:set() and not releasing it, this was out of paranoia so changed it to release after it was noted in review. I now think there was a good reason for it after all.

In CacheCollector::updateCache(), we use a new cache item as a tombstone record for the following case:

1. Process A - cold cache

2. Process B - invalidates the cache (e.g. a state write).

3. Process A writes the cache back at end of request, with stale data from before process B wrote its data.

To avoid this, Process B writes a new cache item, and then process A sees that a brand new cache item has been written when none existed before, and throws its data away instead.

The remaining race condition looked like this:

1. Process A - cold cache
2. Process B - state write and cache write.
3. Process B - end of request - deletes cache item (fails to acquire a lock or any other reason
4. Process A - because the cache item is deleted, doesn't see it, so writes the stale data to the cache.

Holding the lock does the following:

1. Process A - cold cache
2. Process B - state write and cache write
3. Process B - end of request - still has the lock, so writes to cache again instead of deleting.
4. Process A - finds the new cache item so throws its data away

20,000 passes and 0 fails holding the lock, compared to 3/15000 fails without it.

This is probably not enough to prove a negative, but I think it is getting close.

https://git.drupalcode.org/project/drupal/-/jobs/3850861
https://git.drupalcode.org/project/drupal/-/jobs/3850954
https://git.drupalcode.org/project/drupal/-/jobs/3851133
https://git.drupalcode.org/project/drupal/-/jobs/3851201
https://git.drupalcode.org/project/drupal/-/jobs/3851350
https://git.drupalcode.org/project/drupal/-/jobs/3851437
https://git.drupalcode.org/project/drupal/-/jobs/3853860
https://git.drupalcode.org/project/drupal/-/jobs/3854001

edit: 22500 https://git.drupalcode.org/project/drupal/-/pipelines/382543

Couple of general points, mostly answering questions I asked myself while working on this:

This problem is fairly unique to state's use of cache collector. Most cache collector implementations just build a 'runtime' cache from a discovery cache (smaller array from a massive array), so they are not changing values in the underlying data at all.

The most likely problem this change could cause we would be finding badly behaving contrib or custom code that is writing to state every request or something, but that would already cause problems with state caching, the lock wait would make those problems a bit worse, but writing to state every request would be pretty extreme.

With a normal/occasional state write, while the lock is being held, other processes will need to do some extra key/value queries, and won't be able to write back to the cache, but this is relatively cheap (about the same as before we had state caching in the first place). So that bit seems fine.

While adding all the logic, I wondered if state should instead re-implement the parts of cache collector it needs instead of making it more complicated, but:

- overall we'd probably end up with the same amount of complexity, but in two places instead of one
- the changes to cache collector make it more robust for contrib/custom use-cases doing similar things
- even if state moved to 'immediate write' with no end of request lazy-writing at all, it would still have to lock both state writes and cache writes.

There is one possible optimization we can do here which I realised writing the above:

When we write to the cache item in State::set(), if we've acquired a lock, include the other state keys that are already loaded too, that will make it more likely that subsequent requests get a cache hit (including while the lock is being held). Not going to have time to work on that for at least a few hours though.

No we can't do that, because we'd run into the same race condition again in another place - even if we acquire a lock, we don't know what happened immediately before we acquired the lock, so we'd need to do all the same checks on whether the cache item we had at the beginning of the request has changed in the meantime etc. in State::set() too. Maybe if we could factor out some of the logic in updateCache() to re-use, but not easy. Follow-up material, but not sure I want to open it even.

@nicxvan https://git.drupalcode.org/project/drupal/-/merge_requests/10704 is the committable/reviewable branch, it should be up-to-date.

@nicxvan thanks for the stats research, that's pretty encouraging.

I've pushed a revert of #3477586: [random test failure] LayoutBuilderBlocksTest::testBlockPlaceholder failing to the 2500 test runs branch (https://git.drupalcode.org/project/drupal/-/merge_requests/10749) so that it's possible to keep hitting the 'run pipelines' button on there a bit more next week if this isn't committed before then. That will also give us another 2500 runs in the meantime.

Little trip down memory lane:
#20114: race condition in variable_set in bootstrap.inc and #973436: Overzealous locking in variable_initialize() amongst others.

Since it's Monday, started kicking off pipelines again. Will edit this comment to add them when I remember to kick another one off (insert xkcd compiling image).

https://git.drupalcode.org/project/drupal/-/pipelines/387144
https://git.drupalcode.org/project/drupal/-/pipelines/387190

I think we can skip holding the lock after all.

Short explanation of why:

Performance tests were failing in the latest MR, this is because the cli was holding the lock and preventing the site-under-test from acquiring it (annoying).

Trying to workaround this made me realise we're mainly holding the lock to avoid ::updateCache() throwing away the tombstone record when it can't acquire a lock.

Instead of that, if we've acquired a lock, we can completely disable the end of request logic in state, and release the lock. That means as soon as the state item is written other requests can start to build the cache again, without any interference from the ::set() logic.

Obviously, now need to check that this still fixes the race condition so another 10k+ test runs to kick off on the test-only MR - will start that once the main fix MR is green again.

Implemented that. One functional js test failure which I think is unrelated. Updated the test only MR, first 2500 runs came back green, will kick off more over the next 24 hours.

https://git.drupalcode.org/project/drupal/-/pipelines/387799
https://git.drupalcode.org/project/drupal/-/pipelines/387820
https://git.drupalcode.org/project/drupal/-/pipelines/387832
https://git.drupalcode.org/project/drupal/-/pipelines/387846
https://git.drupalcode.org/project/drupal/-/pipelines/387861
https://git.drupalcode.org/project/drupal/-/pipelines/387885

Too much status change.

15k runs without a failure so far, which is pretty encouraging, so I think this genuinely is ready for review again now. I'll kick off some more pipelines tomorrow.

@Spokje yes it should fix cases like that as well.

Several fails on: https://git.drupalcode.org/project/drupal/-/jobs/3923493

These all happened in a cluster of tests where the runtime doubled.

Theory on the above - the runtime doubling could be not acquiring a lock, and having to wait for a second - the runtime doubled when the test itself was holding the lock for the duration of the test (although that prevented any new caching at all so fixed the race condition).

So... trying to be more aggressive when we fail to acquire the lock.

Unrelated fail on https://git.drupalcode.org/project/drupal/-/jobs/3925298, otherwise green.

runs:
https://git.drupalcode.org/project/drupal/-/pipelines/388431
https://git.drupalcode.org/project/drupal/-/pipelines/388538

The simplification led to a behaviour change for the path alias cache, but it's very small and still works.

I think it is probably possible to make updateCache() work for what State:::set() wants to do, but I've already spent a lot of time on this issue and need a break, so I think we should defer that to a follow-up - it might reduce some code and make things hopefully even more robust, but it will be as tricky as this issue to ensure we've caught all the cases. Would rather have things correct which hopefully the current state of the MR gets us to.

Because a few things have changed again, going to run more pipelines..

https://git.drupalcode.org/project/drupal/-/pipelines/390206
https://git.drupalcode.org/project/drupal/-/pipelines/390279
https://git.drupalcode.org/project/drupal/-/pipelines/390291
https://git.drupalcode.org/project/drupal/-/pipelines/390300
https://git.drupalcode.org/project/drupal/-/pipelines/391267 <- failures in this one

Opened #3498317: Try to make State::set() logic re-usable, directly within CacheCollector::updateCache().

Tracked down the very specific race condition with the test (well I think I did) which was still resulting in some failures occasionally - about 1/2500.

I think it is:

1.test requests a page
2. page writes to the state cache collector
3. test sets state
4. test requests a page.

Because the test doesn't use WaitTerminateTestTrait, if #2 is holding the lock while #3 happens, we go into the !$lock_acquired branch in state.

But the implementation so far was concentrating on the request that hits the $lock_acquired branch eventually winning out when it reaches the end of the request (more or less eventual consistency). In the test, there is no 'end of the request', there is just the end of the test, and the page we hit immediately after trying to set state can still get the wrong value in the meantime. The answer is to even more aggressively write to the cache when we can't acquire the lock. It still doesn't work if the underlying request takes longer than a second to complete, because then both the pre- and post- lock acquire attempt cache writes can still be overwritten. We could wait longer than a second, but on a real request the end of request logic is more likely to kick in later and clean everything up.

Bit annoyed that I didn't look at the test in more detail earlier because that's obvious in retrospect, but was trying to focus on the stampede condition that real sites will hit vs functional test weirdness.

Fresh set of runs:

https://git.drupalcode.org/project/drupal/-/pipelines/392873
https://git.drupalcode.org/project/drupal/-/pipelines/393001
https://git.drupalcode.org/project/drupal/-/jobs/3985642 <- 1 fail

@godotislate it's not actually fixing the race condition at the moment so very much needs work - although review of the approach would probably still be useful.

Merged 11.x into the repeat test run MR. One fail in 5000 runs.

https://git.drupalcode.org/project/drupal/-/jobs/4331449

https://git.drupalcode.org/project/drupal/-/jobs/4331562 -> fail

I'm wondering if the remaining test failure is due to #2347867: Race conditions with lock/cache, session storage - add a non-transactional database connection (e.g. a deadlock on the cache/lock table), and if so, that will be unfixable with this MR. Given that, going to rebase the main MR here and move this back to needs review.

Rebased.

Added some unit test coverage for both cache collector and state for everything I can think of.

To some extent this is 'testing the implementation' but to be entirely honest I don't have any other ideas there at the moment.

JsonApiPerformanceTest had a new failure. Debugged it and it was due to the new stricter checks in CacheCollector as to whether we should write a cache item or not. Additional sleep() calls after the cache warming requests fixed it without changing any test assumptions.

Rebased. The unit test now sets up stubs, whereas for the added method we actually want mocks, so I moved several things inline in the method.

If we want to do a large run for #35 we'll need to recreate (probably easier than rebase) https://git.drupalcode.org/project/drupal/-/merge_requests/10749 which restores a state usage in a test that was failing randomly then runs it 2500 times.

Don't think it's failing, rebased in case the bot is picking up a stale branch.

Removed the cruft, added an additional unit test method, and updated the usleep() bit (to also try to simplify it).

I may kind of regret pushing for the state collector cache after reading State::setMultiple(). It's useful, but that complexity is quite a steep price we have to pay for that.

If this one fixes it, or about 99.9% which seems to be the case, then I won't regret it. We're talking about billions, possibly trillions of database queries saved across all Drupal sites, state is right in the middle of the critical path. But yes it is gnarly in there.

Pushed an 11.x backport branch/MR.

If this is a clean cherry-pick to 11.3.x from 11.x we could do that, but if not I'd leave it in 11.4 - only known case of anyone running into this is core test runs, it should be extremely unlikely in the wild.

Rebase is passing except for a parse error in AssetResolverTest on PHP 8.3 which I think is in HEAD, definitely not changed here.

Reverted the main commit - HelpTopicsSyntaxTest started taking 20 minutes, it sets state a lot.

#3586606: Improve performance of HelpTopicsSyntaxTest is in main so this should be OK again.

#3506148: [meta] Replace all uses of state in tests with direct key value should eventually remove all state usage for controlling, um, state in tests. That unfortunately has a high chance of hitting a lock wait because both the test and the site under test will end up trying to write to the cache, via an explicit state set, often multiple times per test method because different state values keep getting set. Exactly how widespread a problem this is likely to be I don't know though. We opened that issue and this one partly due to a high rate of random test failures due to this, not sure how many tests that we didn't already switch to key/value actually fail due to the race condition though at this point.

Kicked off another pipeline to another run to compare against.

Functional 6/8 still a bit slower than the other examples but not as much, very hard to tell if it's the MR or just usual pipeline variation.

https://git.drupalcode.org/project/drupal/-/jobs/9593982

Wall time: 3 min 39 sec
Total time:  1 hour 9 min

real	3m41.728s
user	33m47.443s
sys	4m36.187s

However there's a new performance test fail - probably needs better setup

https://git.drupalcode.org/project/drupal/-/merge_requests/10704/diffs?c... looks good to me visually, however the performance fails suggest it's resulting in different behaviour.

On the other hand there's a green run on #3496328: Use a hash of the cache data for CacheCollector race condition detection so maybe we should merge that issue back into this one? I originally spun it out to make this issue not too much change at once, but not sure it's actually any more or less change really given the complexity here.

OK interesting, well that proves that the behaviour is equivalent, although it doesn't explain why #3496328: Use a hash of the cache data for CacheCollector race condition detection doesn't require the same changes.

I think we should go ahead with #3496328: Use a hash of the cache data for CacheCollector race condition detection which includes all the changes here + additional refactoring on top, so marking this postponed - we can close it once that's in.