Reduce write contention to the fast and consistent backend in ChainedFastBackend

Pushed what I think we need.

Didn't implement the 'additional grace period' because I'm not sure that's what we want. If there are lots and lots of cache sets/invalidations happening, then the $last_write_timestamp will keep being set ahead, and as soon as it's not, that's when we want to write to the fast backend, so what's here might be enough.

However it would be easy to add that additional grace period - we just need to subtract 1 second (or 500ms or whatever) from $compare.

Moving to needs review.

Adding needs profiling because I think that running xhprof on a page request immediately after a cache clear should hopefully show a clear before/after here - e.g. there should be dozens or hundreds less apcu reads and writes but almost no other changes. And then after refreshing that page a couple of times, everything should be the same with/without the MR applied.

Removing the needs profiling tag because by happy accident this made existing unit tests fail, which gave me an idea how we should unit test this - unit test proves that this skips the fast backend when the timestamp is in the future.

However it would probably still be nice to profile it to actually show the real difference in apcu reads/writes.

There's another potential benefit here although it will depend on what actually happens in real-life situations.

Field config entities (for example) aren't usually requested at all when caches are warm, they're used to build things like the views data cache, which then gets cached separately. See #3380145: ViewsData should not cache by language and #3454277: Allow fields to be opted out of views data for some background.

If those higher level caches are built and written during the 'grace period' added here, we won't write field config entities to the fast backend during that time, and then by the time we're out of the grace period, the higher level caches might be all built, which means we don't need to get those lower level cache items anyway, so we don't write them back to the fast backend even after the grace period.

So instead of writing the same amount of data to APCu, but 50ms later and less times, it may result in writing less data to APCu overall.

Might be able to verify this by logging fast backend cache ID writes to a file and comparing after a few page requests with and without the MR.

I ran the following test:

Applied this patch to core:

diff --git a/core/lib/Drupal/Core/Cache/ApcuBackend.php b/core/lib/Drupal/Core/Cache/ApcuBackend.php
index bf5e4d98ca9..39b154255c5 100644
--- a/core/lib/Drupal/Core/Cache/ApcuBackend.php
+++ b/core/lib/Drupal/Core/Cache/ApcuBackend.php
@@ -183,6 +183,7 @@ protected function prepareItem($cache, $allow_invalid) {
    * {@inheritdoc}
    */
   public function set($cid, $data, $expire = CacheBackendInterface::CACHE_PERMANENT, array $tags = []) {
+    file_put_contents('/tmp/set.txt', $cid . "\n", FILE_APPEND);
     assert(Inspector::assertAllStrings($tags), 'Cache tags must be strings.');
     $tags = array_unique($tags);
     $cache = new \stdClass();

drush cr
rm /tmp/set.txt

This clears caches, but then clears out any apcu sets from the command line (e.g. via router rebuilds), so we're only seeing what happens with the first full page load. I could have checked PHP_SAPI instead of requiring the rm set.txt step but it was too late before I thought about that.

Then visited the front page.

Repeated this with and without the MR.

cat set-before.txt | wc -l
1236
cat set-after.txt | wc -l
889

So that's apcu sets reduced by around 1/3rd on the first page load after a drush cr.

This makes me think we should try a longer grace period, so will have a look at that next.

Tried a longer grace period and found more things.

First of all, I realised that in set/setMultiple we always unconditionally write through to the chained fast backend. The idea here was to avoid a consistent cache lookup on the next request (especially in single server setups), but this is the cause of hundreds of writes to the fast backend, which may or may not then be used on the next request anyway - e.g. any low level cache items underneath a layered cache (views data discovery, some plugins derivers) might not be requested on the next request. Also the next write to the consistent backend will invalidate the previous one, so it's 'last one wins' which means hundreds of writes to save one cache lookup on a cold cache, and at maximum one consistent lookup saved on a warmer cache. So I removed those two write-throughs.

This took 889 apcu writes down to just over 120.

I then added the 1 second grace period, and this reduced 120 acpu writes down to 2 or 3.

I then did a further test where I reloaded the Umami front page again after the first couple of steps, and then also clicked over to the 'recipes' page, to see what would happen with a couple more requests, and I got a total of 199 writes. I'm uploading that file - it's not an apples to apples comparison with the previous tests, but it shows that we have less writes even after more activity.

There is probably a bit of discussion to be had about what an ideal grace period should be, but tbh 1 second seems about right, it's usually enough time for discovery caches to be rebuilt, and it's discovery caches (views data, block plugins) are the ones that can result in lots and lots of small config entity and similar cache misses. It's also short enough that the fast backend will start to take load of the consistent backend pretty quickly still - even if we do more writes, if it keeps getting invalidated, the extra fast backend traffic doesn't result in less load.

Added unit test coverage for the ::set issue.

I don't think we have chained fast for items that are requested multiple times per page, for that we have memory/static caching.

The reason is that we have a couple of dozen cache items that are requested on almost any request, especially state, block config for the current theme etc. and we can offload all of those from the database (or redis) for the majority of requests.

Last write per cid would mean as many persistent cache gets as there are fast backend gets and undermine the database offload entirely.

One thing I wondered about was whether we could have the fast backend store a random key to identify the local cache, and add that key to items in the persistent backend, and then only use last_write_timestamp when it doesn't match. This would help on single web head setups a lot, and maybe a bit with more web heads too. It would mean stuffing it into the persistent item transparently (like nesting the actual data in an array with the hash.

You could try to reproduce the steps in #9. The exact numbers will differ every request, but before/after applying the MR should show a big difference.

#3526080-9: Reduce write contention to the fast and consistent backend in ChainedFastBackend

Couple of dodgy looking test failures here, which could be new random failures, but could be unlucky:

https://git.drupalcode.org/issue/drupal-3526080/-/jobs/7370709

https://git.drupalcode.org/issue/drupal-3526080/-/jobs/7370711

Re-running on gitlab CI the standard recipe test fail moved to a different place.

I have a hunch this might be #2066993: Use magic methods to sync container property to \Drupal::getContainer in functional tests, which just became committable. After a rebase, the MR was green first time. Running it a second time just in case to flush anything out.

edit: all green twice. Not perfectly scientific but I think that was probably it.

Can't really explain why this would case them, only idea I have is that by making rebuilds faster that we're more likely to hit race conditions?

Yes that's my only idea too - the MR means we treat the fast backend as invalid more than we do in HEAD (on the basis that it's going to be invalid anyway for a lot of those reads, to save writes to the consistent backend), so I don't see how it could actually introduce a cache mis-match, but it can make an existing race condition more likely by making cold cache requests faster.

We do have #3496257: Race conditions in CacheCollector/State (again) which I got very stuck on, but don't think the failures we saw are related to state.

Because we track the last write timestamp in the consistent backend, this reduces contention in both - updating the title. Also adding a hopeful tag - can go with other stuff in the performance improvements section.