Testing fails 'CI aborted' and 'apcu memory'

Checking memory usage.

Also, sidenote: tests on PHP 7 are a lot slower recently.
8.5.x-dev test with PHP 7 & MySQL 5.5
Sep 12: Took 45 min
Oct 12: Took 48 min
Nov 11: Took 49 min
Dec 12: Took 1 hr 11 min
8.5.x-dev test with PHP 5.5 & MySQL 5.5
Sep 12: Took 1 hr 7 min
Dec 12: Took 1 hr 18 min
PHP 7 is almost as slow as PHP 5.5 now o_O.

Re #10: not sure I follow, what I saw in #8 is that:
1. there's hardly any APCU mem usage (1MB)
2. PHPUnit reporting is inadequate (I think it needed test listener but I didn't finish it)
3. Top offenders are:
Drupal\field_ui\Tests\ManageFieldsTest 94371840 bytes
Drupal\user\Tests\UserPasswordResetTest 92274688 bytes
Drupal\system\Tests\Theme\ThemeTest 83886080 bytes
Drupal\views_ui\Tests\PreviewTest 81788928 bytes
Drupal\field\Tests\FormTest 77594624 bytes
Drupal\quickedit\Tests\QuickEditLoadingTest 75497472 bytes
Drupal\taxonomy\Tests\TermTest 75497472 bytes
Drupal\file\Tests\FileFieldWidgetTest 73400320 bytes
Drupal\menu_ui\Tests\MenuTest 73400320 bytes
Drupal\file\Tests\SaveUploadFormTest 71303168 bytes
so nothing excessive.

Looked over Commits for DrupalCI: Environments and around 23 Nov the php containers were updated, first failure is 26 Nov so this could be environment problem, also it had many updates today and yesterday.

One more problem with #8, those errors are actually forwarded from X-Drupal-Assertion-* headers by Drupal/Core/Test/HttpClientMiddleware/TestHttpClientMiddleware, so they aren't on the test side, those APCU stats cover only the php-cli side, hence low usage.
Edit: except InstallUninstallTest.

#3 and #14 aborted because: Build timed out (after 110 minutes). Marking the build as aborted., all AWS instances are spun down before 2 hour mark.

@vaplas: ok, now i get it, didn't notice that earlier because I'm used to looking at the "View as plain text" version of the log, which doesn't contain the timestamps (as the colored one is sometimes mangled), weird indeed.

@vaplas: not sure if you've read it already, but there's also interesting info about recent changes here #2857788-9: Patch the testbot to start both chrome in webdriver mode and phantomjs in non webdriver mode, especially point 2.

Edit: one run of InstallUninstallTest eats ~6MB of APCU cache.

Edit: Most memory used to serve a page ~100MB, most APCU cache used per test is 1965MB (leaves 35MB free).

@vaplas: That would be just bizzare, maybe it's just the result of @Mixologic and @Mile23 tuning things in the background. But otherwise 47 min test run time is close to what I'd expect from PHP 7.

Out of curiosity, patch from #2930072-14: Module: Convert system functional tests to phpunit + #25.

If there's anything to this, my wild guess would be that lock in index.php somehow helps with ?cache trashing?:
file_put_contents($logfile, date('YmdHis') . ';I;' . memory_get_peak_usage(TRUE) . ';' . $apcuinfo . PHP_EOL, FILE_APPEND | LOCK_EX);

Tests #30

#35: good one, fight random with random, somehow makes perfect sense ;D.

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).

Edit: hiding not intentional (cross-post) ;)

Re #45: I think with #25 it just was lucky first-run, so not much hope for #30, #31.
It does look to me like you're right about #2800873: Add XML GET REST test coverage, work around XML encoder quirks, removing Drupal\system\Tests\Module\InstallUninstallTest in #43 didn't make them faster.

@vaplas: very interesting :)

Trying #50 forced to use localhost for requests.

Edit: also noticed that something is going on with the CI servers, plenty of jobs missing, some have "No tests found" now (https://www.drupal.org/pift-ci-job/835800).

Even if there isn't anything wrong with #2800873: Add XML GET REST test coverage, work around XML encoder quirks itself, it does look like it is responsible for current state of things (as mentioned in #47). I don't hang around REST and test conversion issues so can't really be of much help, if it would 'ring bells' to anyone what might be behind it, I'd expect it would be @Wim Leers.

Re #57: trying more test runs for them.

Also 'Less magic' version ;)

Now also with less manual patch editing bugs ;)

Forgot to release the lock...

Having hard time re-inventing this wheel, might as well use proper one ;)

Edit: yeah, based it on what Symfony did, but botched it somehow, this one uses the proper component.

17:46:23 Error: Status 500 trying to pull repository drupalci/php-7.0-apache: "<html><body><h1>500 Server Error</h1>\nAn internal server error occured.\n</body></html>\n\n"

Edit:
Also this tweet from @drupal_infra.

Aaaaany time now... ;)
Edit: No symfony/filesystem in core...

wtf.php'ed results from #64 and it helps a little, but shuffle still wins.

Patch from #54 + disabled debug output handler.

Edit: apc-usage-track-1.patch: by forcing deleting of expired entries from APCU cache in ApcuBackend it manages to end the tests without filling it up (500MB free at the end), the one fail is just from ApcuBackendTest not expecting this behaviour.

Also, from Drupal\Core\Cache\ApcuBackend:

     // Expiration is handled by our own prepareItem(), not APCu.
    apcu_store($this->getApcuKey($cid), $cache); 

  public function garbageCollection() {
    // APCu performs garbage collection automatically.
  }

I don't think APCU cache works the way ApcuBackend assumes, ApcuBackend doesn't set $ttl

from http://php.net/manual/en/function.apcu-store.php

	ttl
Time To Live; store var in the cache for ttl seconds. After the ttl has passed, the stored variable will be expunged from the cache (on the next request). If no ttl is supplied (or if the ttl is 0), the value will persist until it is removed from the cache manually, or otherwise fails to exist in the cache (clear, restart, etc.).

so it just fills up
Edit: data analysis/graphing failure :(

I'm not sure if this helps, but while working on #2339235: Remove taxonomy hard dependency on node module I just saw a similar situation with an EntityResource. I created #2931027: TermJsonCookieTest is failing locally but TermXmlCookieTest works

Edit: Trying to get an overview of what lurks in the cache, as the usage stats script seems to be compute intensive (aborted bad run in #73) I'm firing it only for the first occurrence, but in order to get it I need to catch a bad run.

@vaplas: that's one way to call it ;) but I think something does not like it, trying to add tests to #76 I keep getting:

403 - Access denied

Unfortunately, you don’t have permission to enter this area of the site.

...so I'll wind my heuristic'ing down for a bit ;D

Amazing work here, I will try to add some comments from another point of view based on other tickets related to APCU.

#1281408: Add a compressing serializer decorator Mention that:

I did some tests on my local machine and it turns out that it is also faster for almost every size of cache data

But also needs profiling. Maybe this issue can help to determine if the use of compressed caches is improving testing speed.

Then, #2765271: Rationalize use of the 'discovery' cache bin, since it's stored in the limited size APCu by default

Gzipping data effectively saves 80% size with minimal CPU cost. We use this compressed backend in redis successfully for quite some months. See

And finally #2832450: Multilingual config cached in "config" cache bin; quickly reaches APCu memory limits

Are some of the resources tests running with different languages?

Heyo, testbot maintainer here.

Feel free to hit me up anytime y'all want to work on a real testbot too. I can put your ssh key on one, and we can set the timeout to however long we need to do any analysis.

And yes, the testbots are now configured to use a network, but really that means that instead of http://localhost, there is just an entry inside of /etc/hosts for the container pointing at 127.0.0.1, so in essence, it'd still using localhost.

Re #55

some have "No tests found"

Thats me doing branch test cleanups. Any passing tests that had a newer, passing build on dispatcher had its build removed. HOwever, it wasnt supposed to cause core to re-fetch those tests, which caused those to not be able to find the result set. I'll have to see why those are re-fetching, and restore them, but assume they are just passing branch tests.

The other thing that has changed recently is that we're now on a different underlying hardware instance (c4.8xl's, and we used to be on cc2.8xls) - which means we have 36 cpus instead of 32.

@Mixologic:
1. if there are 4 more cores, wouldn't it make sense to raise concurrency to 35 ?
2. how to get logs out of an aborted run, the 'Build Artifacts' are somewhat scarce for them (e.g. https://www.drupal.org/pift-ci-job/837848 from #73).
3. any idea what might have caused #78 (had Internet issues at the time so possibly IP changed, but don't see how that could be the cause) ?

Trying to find out what is responsible for flushes.
Edit: incomplete patch, needs work, also there are more players to this, might even be some rogue apcu_clear_cache().

Re #81

1. It might, but I've tried running the testbots on a machine with considerably more cores, and after a certain point, cpu stops being the limiting factor, and there is some other resource blocking. I've been intending to upgrade the kernel on the testbots in order to fire up some eBPF tracing to get us some observability and see if I can make some adjustments. It might be that apache config is the bottleneck, or disk iops, or the db.
2. Theres not a lot we can do to get more build artifacts, other than setting up a special environment that doesnt time out. when jenkins kills the build, it kills it before anything finishes gathering artifacts.
3. I cant really understand how you're getting an http response code in #78 at all? does the file_put_contents resolve to a url or something?

Re #83
Thanks for the info.
3. I mean, when I click Add test / retest trying to add another run I'm redirected to https://www.drupal.org/403 o_O.

Edit: thinking about it, it could just be messed up node_access table entry on d.o.

re-upload of #76
Edit: I think trying to catch it when the apcu_store is already failing is too late, most likely at the same time another request is emptying it.
Also should be apcu_cache_info() instead of apc_cache_info() in original script.

Re #84: nice, too bad apc.entries_hint is PHP_INI_SYSTEM only

Edit: too slow, other request flushed cache before it started gathering statistics, so the one caught is right after the flush.

Re #88: maybe with shuffle+apcu_clear_cache it will go under 15min ;)
Looks like you called it in #23 :).

Perhaps this will do it ?
Edit: botched it again...

Edit: still not able to catch the APCu cache flusher, it might mean it is outside of \Drupal.

Edit: no luck, concurrency 35 variant same as 31, 48 variant slower.

So, this is revealing of something which may be related to apcu in general. It's supposed to *speed things up*, and for a while, we didnt have it at all on the php7 environments, because it didnt exist.

https://www.drupal.org/project/drupalci_environments/issues/2847419

When I added it, we lost about 5 minutes per test.

Adding apcu_cache_clear() at the end of a browser test is *not* just clearing out that tests cache. Its dumping the entire cache, including whatever it is we've got cached for the other 31 processes running elsewhere.

Im guessing that whats going on here is that we're getting heavy apcu fragmentation, we're dumping the whole thing randomly as well:
https://medium.com/@davidtstrauss/avoiding-the-pitfalls-of-apcu-4aa9de00...

I might fire up a server and just completely disable apcu to see what the timing is like.

Re #95: patch in #93 is trying to catch
the code path of flushing mechanism, but I'm still missing something, the Drupal\Core\Cache\ApcuBackend itself tries to play nice with others:

   * APCu is a memory cache, shared across all server processes. To prevent
   * cache item clashes with other applications/installations, every cache item
   * is prefixed with a unique string for this site. Therefore, functions like
   * apcu_clear_cache() cannot be used, and instead, a list of all cache items
   * belonging to this application need to be retrieved through this method
   * instead. 

There is apcu_clear_cache in Doctrine\Common\Cache\ApcuCache (doFlush()), that's why in #82 I mentioned it might be unexpected/done outside of Drupal cache backend (see the apcu-free-over-testrun-40852.png graph).
I also expect plotting @vaplas'es graph with APCu free over time one will show that the flat spots/slowdowns are when the cache is full (my LibreOffice is having issues with the dataset size though ;)).

Then there are also
Drupal\Component\FileCache\ApcuFileCacheBackend, Symfony\Component\ClassLoader\ApcClassLoader that seem to have no concept of flushing.

Here's the chart made from reduced set (5K out of 44K), reason I had problems with graphing might be because some test are running in different timezone and I didn't use UTC (duh!), charts overlaid by hand in graphics editor, so it might have slight offset, but it correlates well enough ;).

I just re-ran the current test suite with apcu completely disabled (well, I hacked all the checks looking for apcu_fetch to look for Xapcu_fetch), and we yielded:

Test run duration: 22 min 10 sec

APCu is not helping the tests run faster.

This will try to gather stats every 5 minutes, instead of hoping for bad run and luck catching (#88 was too slow, other request cleared it when it was trying to gather stats).

Edit: running into php memory limit... but even with barely anything in it (15M) there was 15K entries.

Trying simpler version.

Edit: still exhausting memory, but even at only 253.77MB used there are 250K entries !

20171221105042-0800;D;Free: 1736.04MB
Entries: 250974
Total user: 253.77MB

133623k - drupal.class_loader
42022k - drupal.file_cache
84216k - drupal.apcu_backend

Trying to get it raw.

Edit: this won't work, logs would be GB in size.

Edit:
apc-usage-track-2.4.3.patch: won't work same reason as #101
apc-usage-track-2.4.4.patch: still not enough memory

Just tried a test run with 8gb of apcu, php7, sqlite.

Test run duration: 54 min 34 sec

@Mixologic: try changing apc.entries_hint (to ??? 1-2 millions ???).

Edit: 4GB does the trick ;)

20171221230010+0000;D;4096M;Free: 278.4MB
Entries: 1659684
Total user: 1658.57MB

883892k - drupal.class_loader
276535k - drupal.file_cache
537951k - drupal.apcu_backend

A lot of 1K bootstrap:user_permissions_hash:authenticated,ayl5fozd style entries. Leads to Drupal\Core\Session\PermissionsHashGenerator::generate().

Very interesting. with apc.entries_hint = 4500000: Test run duration: 22 min 36 sec

Edit: also with apc.shm_size = 8000M

Modified patch from #89.

@Mixologic: noticed some things poking around:
1. SQLite testruns are only so quick because they don't actually run anything for --types "PHPUnit-FunctionalJavascript" part (see HEAD https://dispatcher.drupalci.org/job/php7_sqlite3.8/5258/)
2. there's relatively new error in apache-error.log:
sh: 1: -t: not found
possibly this ?
3. there's another one in test.apache.error.log
[Thu Dec 21 11:51:33.170639 2017] [:error] [pid 27182] [client 172.18.0.3:33143] PHP Warning: POST Content-Length of 8392099 bytes exceeds the limit of 8388608 bytes in Unknown on line 0, referer: http://php-apache-jenkins-php7-mysql5-5-4554/subdirectory/node/add/article

Re #106: @vaplas'es hunch from #23 100% confirmed, good he stuck to it in spite of my sidetracking :D

Im skipping the FunctionalJavascript tests on purpose. they run one at a time, and dont do a whole lot to apc anyhow. But interesting that there must be some kind of bug with my recent deploys for sqlite and functionaljavascript tests, so the speed Im reporting is purely the first run of tests, and just run-tests.sh, not the whole build.

2. Thats definitely something trying to send mail. Seen that before.
3. Im not sure what would be posting 84mb articles as a test. does that always happen, or just sometimes?

I tried another test with setting the apc.ttl = 300 to keep the cache evicting on a regular basis, but also keep the shm_size down to 2000M + apc.entries_hint = 1500000

The entries did hover between 900,000 and 1,200,000, fragmentation was at 100% and the tests took Test run duration: 25 min 45 sec

So, Im not totally sure what the best option here is. We definitely want to hint the apc entries, but we also need to clear those out. I dont know enough about the cache bin key system to know whether or not adding another step at the test cleanup phase to iterate over all the cache keys set during a test and evicting them manually will save us any time, or how quick that'd be.

But regardless, we know that we either need to do something to keep memory usage down, or we need to bump up the apc.shm_size to something massive (6-8gb) to never have errors/issues.

Im very tempted to say this is a critical bug in the APC Cache Backend, and that it should properly handle an apc_store() that fails (if it can)

Just for more confirmation, setting the shm_size to something small, like 200M, took 2 hrs, 36 min to run, and had 15531 exceptions for 'unable to allocate memory for pool'.

So too small creates memory errors, but big enough to hold everything becomes so unwieldy that test time doubles.

Perhaps the best thing really is to set the ttl, unless we have a way to clear out *just* a single tests cached entries.

Re #109:
1. yes, I meant daily testing, not the speeds reported here
3. article is ~8MB in size, just 3.5K over the limit, will try to track that down

Re #110:
selective cleaning should be possible for ApcuBackend, not so sure about ApcuFileCacheBackend and ApcClassLoader, apc.ttl set to default (0) is bad indeed, went over the issues that touched ApcuBackend to see what the intention was but didn't find much besides #2581395: Incorrect expiration in APCUBackend that removed $ttl parameter from apcu_store() calls.

Re #111:
Thanks for proper charts and the script, mine was a bit of a pain, LibreOffice kept crashing or taking forever just to resize/change something even with one data series, so just painted it over your chart ;), also need to start using gmdate() to get consistent timestamps in mem-index.log. #2272685: Incorrect handling of invalid cache items in apcu backend might be a step in the right direction indeed.

More memory tracking.
Edit: makes no difference but confirmed 'expunges' are responsible for flushes.

Re #117: Thanks for the charts :)

Patch trying to limit the main polluter (ApcClassLoader).
Edit: much better... needs more work though
under 1M entries per test-run

Same for ApcuFileCacheBackend.
Edit: better still. under 300K entries per testrun.

@vaplas: Thanks :D, aaaalmost there, there might be some problems with this approach judging by the test failures, might get faster yet with proper hinting in environments, and increasing cache size to 2,5GB.

wow wow wow. This is awesome work.

Re #126: #124 is equivalent to #120, while trying to make those bins reusable I noticed that this was just re-inventing it. Random fail in UpdatePathTestBase tests was caused by garbage collector bug (#2828559: UpdatePathTestBase tests randomly failing).

Just to be sure, patch from #126 with logging.

Edit: yup, speed and entries-wise same as #120 and #124 but less hack'y and without the failure, still would like to see how it fares on environments with proper hinting but it's pretty much up to the maintainers what to do now.

Re #132: Thanks for correction :D, applied wrong patch (apcu-ensure-unique-prefix-false-mem-track.patch) on top of yours, no idea how I managed to do that (/facepalm).

Re #128: some of the bins (especially drupal.apcu_backend) are required to be per-instance (that's why I only touched drupal.class_loader and drupal.file_cache).
Drupal\Core\Cache\ApcuBackendFactory does:

  public function __construct($root, $site_path, CacheTagsChecksumInterface $checksum_provider) {
    $this->sitePrefix = Settings::getApcuPrefix('apcu_backend', $root, $site_path);
    ...
  }

hence the failures.

Edit: 2930022-124-prod-mem-track.patch: around 400K cache entries and slightly lower hits/misses ratio (93).

Checked for /core/rebuild.php in #93, looks like it isn't tested/used during testrun (log).

@vaplas: not sure, but it could be because updates are run via Batch API and $this->checkForMetaRefresh(); just waits for batch to finish.
Edit: still 4069 is quite a bit too long.

I don't know how to help here, except say … WOW, impressive research! 😲👏

@vaplas: For me the failure part is pretty much figured out now, the fix is already implemented so it is just about re-enabling it, I'm all for leaving APC enabled on test runners (even if it doesn't make much difference in speed there as everything is running from RAM anyway - it is important on live sites, so stress testing it is valuable), so +1 for #2926309-43: Random fail due to APCu not being able to allocate memory.
Before doing more tuning I'd like to see apc.entries_hint increased in environments (as a follow-up to #2926309: Random fail due to APCu not being able to allocate memory), to make sure we're not dealing with the same bottleneck.
I would also like to see some hook_requirements follow-up to warn users if their apc.entries_hint is set too low, but that might be tricky, would need to figure out how much standard install is using, to at least recommend something within the order of magnitude.