Random fail due to APCu not being able to allocate memory

This is happening heaps (pun) today, so promoting to critical. I don't think it's a core issue so we should probably move it to the appropriate queue, but tracking here for now.

https://www.drupal.org/pift-ci-job/824165

Here are a couple of issues which might help to determine problem:

#2765271: Rationalize use of the 'discovery' cache bin, since it's stored in the limited size APCu by default
#2800605: Warn/inform users when the hosting environment has a too low limit of APCU cache
#2832450: Multilingual config cached in "config" cache bin; quickly reaches APCu memory limits

Here another fail from https://www.drupal.org/project/drupal/issues/2627512

https://www.drupal.org/pift-ci-job/833314

Adding more example to the report from this issue #2920963: Remove the migrate.migration prefix from core test migrations

That DEFAULT_MAX_ROWS was just a stab at figuring out what is slowing the PHP 7 testing down, but it went in 12 September 2017 so I don't think it is likely.
Randomizing order in #2930022-35: Testing fails 'CI aborted' and 'apcu memory' on the other hand seems to be consistent, and gives around 30 minute reduction in test time for PHP 7.
Will try to narrow down which tests take so long by processing the logs.
Also #2930022-25: Testing fails 'CI aborted' and 'apcu memory' shows that both good and bad runs have the same memory usage (~100MB max to serve a page and 35MB left in APCU cache).

Is the graph saying there are around 175 tests heavily slowing down the testing, from 12-15 minutes after the testing has started?
Can they be the source of the issue (it's out of memory after all...)?

Processed test durations attached.
In fast run (#25) Drupal\system\Tests\Module\InstallUninstallTest takes 10 minutes, in the slow one (#8) it lingers for 47 minutes and there's plenty of slow Drupal\Tests\rest\Functional\* tests (they are at least 10x slower vs fast run).

There also seems to be an issue with ApcuBackend assuming APCU storage works like Memcached (LRU eviction) and filling up (see #2930022-73: Testing fails 'CI aborted' and 'apcu memory').
Edit: nevermind that, the fail here was in my data processing skills, graph actually shows that when the APCU cache fills up it is flushed completely.

APCU free over testrun:

@vaplas completion script for the testrun:

# of requests per second over testrun:

graph actually shows that when the APCU cache fills up it is flushed completely.

That sounds like a really risky property for a cache backend. I dont think I would use it.

Re #26: trying to figure out the exact mechanism, those apcu_store errors do seem to pop out when the cache is nearly exhausted and there are many requests in flight at the same time (e.g. for test run in #25 at the second dip when it has 35MB free - request #33909, timestamp 20171216001325).

Re #27: could be something to it, digging into apcu-5.1.8.tgz, check apc.entries_hint, also some info in apcu-5.1.8\TECHNOTES.txt, will keep trying to characterize its content.

So, something is kinda terrible with how we're using apcu, at least on the testbots.

In the php7/sqlite environment, if I bump the cache to 8gb of memory so that we can fit everything without ever having to evict, the test time goes up to Test run duration: 54 min 34 sec

With it set to 2GB, we see anything from 27-32 minutes typcially

If I *shut it off entirely*, it goes down to Test run duration: 22 min 10 sec

So, these 'random errors' are race conditions in apcu that manifest when you try and have 32 processes cramming 4.5 million objects into it and never do any cleaning of all the cached data in there.

Is there any way that we can empty all the cached data for a test when that test is complete?

APCu not being a real LRU cache make it horrible to deal with.

Is there any way that we can empty all the cached data for a test when that test is complete?

The main challenge with this is that the backend doesn't keep track of what $bin:$cid got set throughout the lifetime of a request. So the potential solution would be to

- add a property which would track $bin:$cid
- set/delete would have to do the housekeeping
- we would have to add a __destruct() to iterate and apcu_delete($bin:$cid)

We would probably also want to subclass ApcuBackend to ApcuLifetimeBackend for BC, and because we really only want to do this for tests (and someone may find a use for this outside of testing, similar to the in-memory one).

Re #26: trying to figure out the exact mechanism, those apcu_store errors do seem to pop out when the cache is nearly exhausted and there are many requests in flight at the same time (e.g. for test run in #25 at the second dip when it has 35MB free - request #33909, timestamp 20171216001325).

IME you hit APCu errors not due to it emptying, but due to it not emptying when it's fragmented.

Let's say you have a 1mb item to cache, and two slots with 500kb each. You now cannot write the item (hence the unable to allocate error), but also APC isn't 'full' so it doesn't clear out.

@Mixologic is right though. The way we use APCu in core is fine for single site situations, since the cache size is finite. It should never be used for multiple sites on one server and that's what we're doing with the test bot.

We could possibly do something in functional tests to removeBin() from child sites on test completion. Might help a bit. Or we might need to not test with APCu except for actual cache tests.

IME you hit APCu errors not due to it emptying, but due to it not emptying when it's fragmented.

IIRC, that is only the case when you are using TTLs. With "permanent" entries, it should dump. I have an old, old issue in the PHP issue queue trying to get clarification on the exact strategy that it uses, but I don't think it ever got answered. My understanding is my memory (ha!) of reading the code.

I think disabling APCu for tests and seeing what the impact on run times is the best option right now; my guts says that removeBin() on teardown may cause different problems.

@vaplas was right in #27.2 and much earlier in #23, the slowdowns are all from apc.entries_hint defaulting to 4K and the tests cramming there 5M of variables, confirmed by @Mixologic #106.
Also see graphs he made in #111, they correlate test completion with free cache.

There are also some logs to give you idea what's in the cache over time (#105:1, #105:2 - script by @msonnabaum from here).
There are a lot of 1K bootstrap:user_permissions_hash:authenticated,ayl5fozd style entries, which leads to Drupal\Core\Session\PermissionsHashGenerator::generate().

Still not sure what does the actual flushes, tried to catch it in #93 (log), for all I know it might even by done outside of Drupal's cache system (there's apcu_clear_cache() call in Doctrine\Common\Cache\ApcuCache (doFlush()).
Then there are also
Drupal\Component\FileCache\ApcuFileCacheBackend, Symfony\Component\ClassLoader\ApcClassLoader that seem to have no concept of flushing/gc.

Drupal\Core\Cache\ApcuBackend used to set $ttl at some time but it was removed in #2581395: Incorrect expiration in APCUBackend.

I'm sure the apc.entries_hint needs adjusting in the test environments, maybe even apc.ttl (see #109), or at least some requirement check (does ApcuBackend make an assumption that it will be set some specific way ? 0 or fixed time).
But it feels like ApcuBackend needs to do something too.

Also for some tries of cleaning after tests: #89, #107, #111, #113, still WIP.

Re #32: @Mixologic did that in #98, they run much faster without APCu ;).

From apcu-5.1.8\INSTALL:

apc.ttl                 The number of seconds a cache entry is allowed to
                            idle in a slot in case this cache entry slot is 
                            needed by another entry.  Leaving this at zero
                            means that your cache could potentially fill up
                            with stale entries while newer entries won't be
                            cached.  
                            (Default: 0) 

says noting of 'emergency dumping', still checking code.

apc.smart  If you begin to get low on resources, an expunge of the cache
           is performed if it is less than half full. This is not always
           a suitable way of determining if an expunge of the cache
           should be per
           apc.smart allows you to set a runtime configuration value which
           is used to determine if an expunge should be run
           if (available_size < apc.smart * requested_size)
             apc_cache_expunge()
           (Default: 0) 

apcu-5.1.8\TECHNOTES.txt:

While walking the linked list we also check to see if the cache has a TTL defined.
If while walking the linked list we see a slot that has expired, we remove it
since we are right there looking at it.  This is the only place we remove stale
entries unless the shared memory segment fills up and we force a full expunge via
apc_cache_expunge().  apc_cache_expunge() walks all slots attempting deletion, how
deletion occurs depends on runtime parameters, see INSTALL for runtime parameter
configuration details. 

Now for the code part, TLDR: it does nuke it.

apcu-5.1.8\apc_cache_api.h:

/* {{{ apc_cache_default_expunge
* Where smart is not set:
*  Where no ttl is set on cache:
*   1) Perform cleanup of stale entries
*   2) Expunge if available memory is less than sma->size/2
*  Where ttl is set on cache:
*   1) Perform cleanup of stale entries
*   2) If available memory if less than the size requested, run full expunge
*
* Where smart is set:
*  Where no ttl is set on cache:
*   1) Perform cleanup of stale entries
*   2) Expunge is available memory is less than size * smart
*  Where ttl is set on cache:
*   1) Perform cleanup of stale entries
*   2) If available memory if less than the size requested, run full expunge
*
* The TTL of an entry takes precedence over the TTL of a cache
*/
PHP_APCU_API void apc_cache_default_expunge(apc_cache_t* cache, size_t size); 

/*
* apc_cache_real_expunge: trashes the whole cache
*
* Note: it is assumed you have a write lock on the header when you enter real expunge
*/
PHP_APCU_API void apc_cache_real_expunge(apc_cache_t* cache); 

apcu-5.1.8\apc_cache.c:

PHP_APCU_API void apc_cache_default_expunge(apc_cache_t* cache, size_t size) 
{
...
	/* make suitable selection */
	suitable = (cache->smart > 0L) ? (size_t) (cache->smart * size) : (size_t) (cache->sma->size/2); 
...
	/* perform expunge processing */
	if(!cache->ttl) {

		/* check it is necessary to expunge */
		if (available < suitable) {
			apc_cache_real_expunge(cache);
		}
	} else {
	...
	}
}

The triggers are inside apcu-5.1.8\apc_sma.c (notes after ###):

PHP_APCU_API void* apc_sma_api_malloc_ex(apc_sma_t* sma, zend_ulong n, zend_ulong fragment, zend_ulong* allocated) { 
...
    off = sma_allocate(SMA_HDR(sma, sma->last), n, fragment, allocated);
    
    ### first tries to expunge last segment
    if(off == -1) {
        /* retry failed allocation after we expunge */
        WUNLOCK(&SMA_LCK(sma, sma->last));
		sma->expunge(
			*(sma->data), (n+fragment));  
        WLOCK(&SMA_LCK(sma, sma->last));
        off = sma_allocate(SMA_HDR(sma, sma->last), n, fragment, allocated);
    }
... ### skipped one going over all other segments
    ### if that didn't help it just nukes it anyway
    /* I've tried being nice, but now you're just asking for it */
    if(!nuked) {
        sma->expunge(*(sma->data), (n+fragment));
        nuked = 1;
        goto restart;
    }
...
}

Can also be verified experimentally as it keeps the count under 'Cache full count'

apcu-5.1.8\apc.php:
'<tr class=tr-1><td class=td-0>Cache full count</td><td>{$cache['expunges']}</td></tr>',

apcu-5.1.8\apc_cache.c:
add_assoc_double(&info, "expunges", (double)cache->header->nexpunges);
so @Mixologic could confirm that it is the case by catching the same apc.php stats screenshot as in #29 but with default settings.

Edit: confirmed (last column is apcu_cache_info(TRUE)['expunges']).

I would love to shut of APCu on the testbots.

A not insignificant amount of time is spent waiting for memory locks.

I've uploaded the status of the APC cache directly after running the default, which took 31 min, 20 to run just the phptests on php7/sqlite.

I then changed just the apc.entries_hint so that it had more than 4096 buckets to use, but that made things worse: 54 min 40 sec.

Finally, I just flat out shut it off.

14 min 14 sec.

Now that we're paying by the minute, I can pretty much quantify this to saving 0.12 per test, which sure would be nice to get that back. (not sure the impact it would have on the php5.5/5.6 envs, but probably similar)

The PHP 7 & SQLite 3.8 of #120 does 14 min 1 sec.

$settings['apcu_ensure_unique_prefix'] = FALSE;

This is actually a nice find, given that #2474909: Allow Simpletest to use the same APC user cache prefix so that tests can share the classmap and other cache objects was introduced only for this reason in the first place :)

And then removed by #2749955: Random fails in UpdatePathTestBase tests.
Edit:
Making ApcClassLoader shared across the tests lowers the amount of APCu cache entries over the test-run from 5M to 1M (hits/misses = 39, right before the expunge), with ApcuFileCacheBackend added it gets reduced to 300K (hits/misses = 117, charts courtesy of @vaplas).

So, if we want to go with #41

1. +++ b/core/lib/Drupal/Core/Test/FunctionalTestSetupTrait.php
   @@ -41,6 +41,13 @@
   +   * Setting unique apcu prefix. See Settings::getApcuPrefix().
   +   *
   +   * @var bool
   +   */
   

   Nits, but first line should be one sentence, and should use a @see

2. +++ b/core/tests/Drupal/Tests/Core/Site/SettingsTest.php
   @@ -117,7 +117,7 @@ public function testSerialize() {
   -    $settings = new Settings(['hash_salt' => 123]);
   +    $settings = new Settings(['hash_salt' => 123, 'apcu_ensure_unique_prefix' => TRUE]);
   

   Nice, esp when you see this in context.

Since this is the third(?) time we have had to tweak this, I think we should expand the comments on Settings::getApcuPrefix() about what is going on, and reference #2474909: Allow Simpletest to use the same APC user cache prefix so that tests can share the classmap and other cache objects, #2749955: Random fails in UpdatePathTestBase tests, and this issue.

And kudos to @valpas and @tacituseu on this. I have run into some other instances where caching slowed things down. The profiling / charts are awesome, and are really needed to draw real conclusions.

Just adding the patch w/ shuffles to see if there are any side effects.

One important result of all this amazing research is that real sites also potentially has issues with that. Unlike the initial benchmarks we did (clear all cache, just access the frontpage), real sites tend to have actually a lot of more code involved over time.

I'm curious whether @berdir made any research on the same topic as well. They have D8 production sites since a long time.

Marking #43 RTBC, it's a shame we already thought about this, removed it as a hotfix, then forgot about it until now but all the work here has been really useful regardless. I think we should open a (major) follow-up to discuss this more so we don't lose all the information here.

Whoops I just nearly cross-posted because I'd opened #2934002: APCu cache backend can have unreasonable number of entries during testing or multi-site. Let's mark one as duplicate (I haven't done so yet though).

+++ b/core/lib/Drupal/Core/Test/FunctionalTestSetupTrait.php
@@ -41,6 +41,18 @@
+   * Wide use of a unique prefix can lead to problem with memory, if tests are

nit: => problems, can be fixed on commit

Just a note that we stopped WTB sharing the same APC key in #2749955: Random fails in UpdatePathTestBase tests. So we have to be wary that doing this will introduce other random fails.

Let's see if we still have random fails in the update tests...

lol the test has moved...

So we're not seeing any super often random fails because of reverting #2749955: Random fails in UpdatePathTestBase tests - so +1 to going forward with #52. Re-uploading so that that is the last patch on issue.

I ran the patch in #52 and APC still overflowed once.

I bumped the apc.entries_hint to 500,000 to give it a better subdivision, and bumped the memory to 3GB to see if I could avoid an overflow. Attached is the final apc dashboard, so no overflows, but it still needs about 2.4 GB of memory.

Im excited to get this patch in to reduce random fails, as well as a significant performance boost for the testbots, which translates into cost savings for the DA.

It would still be nice to see if its possible to clear out a prefix at the end of a test, but that could mean more overhead than it's worth.

To clarify some things, I'll bump APC's memory to 3GB as well as the entries hint to help reduce testbot errors. On one hand, that might hide issues that real world users have if their APC memory is lower than required, but given that we're not really mimicing real world scenarios with the way we run the tests, I think its better to err on the side of not having tests fail randomly.

Committed 9d552ca and pushed to 8.5.x.

Leaving at RTBC and changing to 8.4.x.

Will cherry-pick to 8.4.x tomorrow after commit freeze for 8.4.4 is over.

Tagging with my made-up tag until such time.

@Mixologic: at the same time it can also be reduced in php-cli.ini's, as the run-tests.sh side is hardly even using it (tens of MB max).

@vaplas: first place is right the way it is :) awesome work.

Added catch and dawehner to issue credits

What is follow-up issue to research cleaning cache by prefix? Should not be so hard to make it in tearDown()

We can look at it in #2934002: APCu cache backend can have unreasonable number of entries during testing or multi-site or possibly make a child issue of that one?

Just a reupload so we have runs against 8.4.x.

Cherry-picked as 527e762 and pushed to 8.4.x

Made the commit message for the cherry-pick reference @catch and @dawehner as per #71