Page MenuHomePhabricator

Phorge setup check caching is misbehaving, leading to many duck-sound=quack requests
Closed, ResolvedPublic

Description

Flagged earlier today by @RLazarus: There are a lot of requests for phabricator.wikimedia.org/test-%2A/?__path__=%2ftest%2d%252A%2f&duck-sound=quack in phabricator.wikimedia.org Apache logs. They're coming from phab1004 itself.

After some digging, this may be an upstream Phorge bug, or may be specific to our deployment. @Dzahn notes that it's been noticed in the past, but there are a lot of these now and something seems weird. Notes follow.

  • ~193400 hits in phab1004:/var/log/apache2/phabricator_access.log
  • These are from PhabricatorWebServerSetupCheck.php +38.
  • The setup checks can potentially fire on every request, but should be cached.
  • There are two layers of relevant caching for setup issues:
    • A setup-specific cache that uses either APCu or files in /tmp
    • phabricator_cache.cache_general in the database, stored as a JSON string.
  • I should verify that APCu is enabled on phab1004.
  • There's a one-line change to PhabricatorSetupCheck::getOpenSetupIssueKeysFromDatabase() that may have been deployed only recently: f2a01dca392 - I can imagine that being relevant, although it's not immediately obvious how.

@thcipriani:

My tracing through this went: index.php -> AphrontApplicationConfiguration::runHTTPRequest -> PhabricatorSetupCheck::willProcessRequest -> PhabricatorSetupCheck::getOpenSetupIssueKeys -> check APC (in PhabricatorCaches) and if that comes back null it'll call PhabricatorSetupEngine which I think will check the webserver setup which started this rabbithole

In production, the database row for phabricator.setup.issue-keys seems to be an empty array and gets reset frequently:

mysql:phuser@m3-master.eqiad.wmnet [phabricator_cache]> select * from cache_general where cacheKey = 'phabricator.setup.issue-keys';
+-----------+--------------+------------------------------+-------------+-----------+--------------+--------------+
| id        | cacheKeyHash | cacheKey                     | cacheFormat | cacheData | cacheCreated | cacheExpires |
+-----------+--------------+------------------------------+-------------+-----------+--------------+--------------+
| 302713914 | K3VntSub8LL2 | phabricator.setup.issue-keys | raw         | []        |   1754337833 |         NULL |
+-----------+--------------+------------------------------+-------------+-----------+--------------+--------------+

mysql:phuser@m3-master.eqiad.wmnet [phabricator_cache]> select * from cache_general where cacheKey = 'phabricator.setup.issue-keys';
+-----------+--------------+------------------------------+-------------+-----------+--------------+--------------+
| id        | cacheKeyHash | cacheKey                     | cacheFormat | cacheData | cacheCreated | cacheExpires |
+-----------+--------------+------------------------------+-------------+-----------+--------------+--------------+
| 302713914 | K3VntSub8LL2 | phabricator.setup.issue-keys | raw         | []        |   1754337842 |         NULL |
+-----------+--------------+------------------------------+-------------+-----------+--------------+--------------+

On phab.wmflabs.org, this row is populated and was last set hours ago:

MariaDB [phabricator_cache]> select * from cache_general where cacheKey = 'phabricator.setup.issue-keys' \G;

          id: 10625
cacheKeyHash: K3VntSub8LL2
    cacheKey: phabricator.setup.issue-keys
 cacheFormat: raw
   cacheData: ["aphlict.connect","mysql.max_allowed_packet","sql_mode.strict","mysql.local_infile","extension.zip","php.post_max_size","config.unknown.gitblit.hostname","config.unknown.gitlab.api_key","elastic.misconfigured"]
cacheCreated: 1753684863
cacheExpires: NULL

Details

Event Timeline

Regarding APCU:

On phab1004 I can confirm the Debian package is installed:

dpkg ...

php-apcu					install

I can also confirm it's configured to be loaded:

cat /etc/php/7.4/fpm/conf.d/20-apcu.ini 
extension = apcu.so

BUT, actually running a phpinfo() shows:

Configuration

apcu

APCu Support => Disabled
Version => 5.1.19
APCu Debugging => Disabled

BUT, actually running a phpinfo() shows:

This might differ for php-fpm rather than cli, but I do note it's not mentioned in either php.ini.

/etc/php/7.4/fpm/conf.d/20-apcu.ini

[phab1004:~] $ cat /tmp/check.php 
<?php
echo "APCu: ", extension_loaded('apcu') ? 'OK' : 'MISSING', "\n";
?>


[phab1004:~] $ php /tmp/check.php 
APCu: OK

...
BUT, actually running a phpinfo() shows:

Configuration

apcu

APCu Support => Disabled
Version => 5.1.19
APCu Debugging => Disabled

That is because, is disabled from via apcu.enable_cli which default to false for the CLI and thus disables APCu when invoking /usr/bin/php.

For php-fpm SAPI, it is enabled:

$ /usr/sbin/php-fpm7.4 -i|grep 'APCu Support'
APCu Support => Enabled

Question: Do we still have data if the number of duck-sound=quack requests was roughly the same level before and after our 2025-07-15 15:30UTC deployment in T370266? (If it was the same, that would rule out f2a01dca392.)

I have a vague theory but first need to poke code a bit more.

FYI,

Question: Do we still have data if the number of duck-sound=quack requests was roughly the same level before and after our 2025-07-15 15:30UTC deployment in T370266? (If it was the same, that would rule out f2a01dca392.)

If anything, it seems to have fallen off?

deploy.png (1,120×905 px, 97 KB)


Checking the production database just now, I discovered that this seems to have stabilized some, or at least to be fairly bursty at the moment:

  • grep -c duck-sound /var/log/apache2/phabricator_access.log gives 141436, 141468 a few minutes later, 141652 currently
  • The cached value in the db has only been updated a handful of times in 10 minutes

Turnilo webrequest_sampled_live for phabricator.wm.o 4-6 August, first from phab1004 to itself:

1.png (1,117×381 px, 23 KB)

And then just general requests:

2.png (1,117×382 px, 22 KB)

Makes me wonder if this has to do with pressure on the cache and/or volume of overall requests.

brennen triaged this task as Medium priority.Aug 5 2025, 6:33 PM
brennen moved this task from Backlog to Waiting Response on the User-brennen board.

With the above mitigation in place, this seems less urgent in terms of web requests, but I'd still like to get to the bottom of it.

Current working theory is setup check values falling out of APCu cache, so we're going to try increasing size on that, and I'll poke at visibility into state of cache. (The default is 32M.)

Change #1175916 had a related patch set uploaded (by Dzahn; author: Dzahn):

[operations/puppet@production] phabricator: increase APCu shared memory segment size

https://gerrit.wikimedia.org/r/1175916

FYI I discovered https://phabricator.wikimedia.org/config/cache/ which states that APCu has "31 MB" and OPcache has "128 MB".
It also lists Memory Usage values and the number of Cache entries. No idea though how often that gets updated.

What a great finding! I am capturing the values here as a baseline:

CacheMemory UsageEntries
Opcode60.5% of 128 MB6196
Data53.8% of 31 MB181

Most of the entries are cumulatively small. The largest one is for phabricator:PhabricatorRepositoryGraphCache:N:N:N (32 entries, Total of 16MB, largest 1MB).


In production we do monitor APCU/Opcode cache. Graphs can be found on mediawiki-on-k8s dashboard under the APCU and Opcache sections. Ideally anything that uses php-fpm should have those metrics collected? :)

In prod we had modules/profile/files/mediawiki/php/admin/index.php (and its associated lib.php). It exposes a bunch of PHP metrics in a format suitable for Prometheus collection ( https://gerrit.wikimedia.org/r/c/operations/puppet/+/475457 ).

Checking after lunch:

CacheMemory UsageEntries
Opcode60.5% of 128 MB6201
Data39.5% of 31 MB161

phabricator:PhabricatorRepositoryGraphCache:N:N:N now has 24 entries (Total of 11MB).

I have refreshed the page and:

CacheMemory UsageEntries
Data3.7% of 31 MB141

phabricator:PhabricatorRepositoryGraphCache:N:N:N has a single entry of 415 KB. So that definitely got flushed?

Code of the cache is:
https://gitlab.wikimedia.org/repos/phabricator/phabricator/-/blob/wmf/stable/src/applications/repository/graphcache/PhabricatorRepositoryGraphCache.php

In src/applications/cache/PhabricatorCaches.php it is set to have a maximum of 32 entries

Maybe that cache is overflowing APCu?

Note there is a second level cache which is in the database so we should find the entries (and their size) from the DB.

Change #1175916 merged by Dzahn:

[operations/puppet@production] phabricator: increase APCu shared memory segment size

https://gerrit.wikimedia.org/r/1175916

Mentioned in SAL (#wikimedia-operations) [2025-08-19T17:10:43Z] <mutante> phab2002/phab1004 - systemctl restart php7.4-fpm after we increased APCu shared memory segment size (T401157)

After deploying the config change (and restarting php7.4-fpm) we can now see on https://phabricator.wikimedia.org/config/cache/

Opcode Cache: Memory Usage
    49.1% of 128 MB 

APCu Data Cache: Memory Usage
    0.3% of 255 MB

The APC cache has been raised to 256MB. I thought phabricator:PhabricatorRepositoryGraphCache was limited to 32 entries in the APC/L1 cache and given the objets had a largest size of 1MB that would have fit. Unfortunately checking now after browsing https://phabricator.wikimedia.org/source/skins/ and of its branches:

PatternCountLargestTotalUsage
phabricator:PhabricatorRepositoryGraphCache:N:N:N3661 MB148 MB58.2%

With 366 items, I guess I have misunderstood the setLimit(32) I had read for that cache.

One sure thing, that cache is overflowing the APC cache which is shared by other caches and ends up being emptied as a result. That in turns cause PhabricatorSetupCheck::getOpenSetupIssueKeys to regenerate the checks. Maybe that one can have a L2 cache backed up in the database :)

The 256MB cache ends up being filed as well:

PatternCountLargestTotalUsage
phabricator:PhabricatorRepositoryGraphCache:N:N:N5954 MB232 MB90.7%

And eventually after a refresh it went down to 287 objects and 130MB.

To reproduce:

Change #1180643 had a related patch set uploaded (by Brennen Bearnes; author: Brennen Bearnes):

[operations/puppet@production] phabricator: bump APCu shared memory size to 4096M

https://gerrit.wikimedia.org/r/1180643

Change #1180643 merged by Dzahn:

[operations/puppet@production] phabricator: bump APCu shared memory size to 4096M

https://gerrit.wikimedia.org/r/1180643

It still shows 128MB there. Let me do some restarts to change that.

opcache is 128M, which I think is basically fine - I haven't seen that fill up.

APCu data cache says 3GB, which reflects the new value - not sure where it maxed out on usage; I haven't seen it go above 15% or so.

Shall we revert https://gitlab.wikimedia.org/repos/phabricator/phabricator/-/merge_requests/93

Probably a good idea, though there's some stuff in there I suspect could be removed upstream.

FYI server logs mention this twice from last Friday around 1430UTC:
PHP Fatal error: Uncaught Error: Call to undefined function apcu_stats() in /srv/deployment/phabricator/deployment-cache/revs/22fcde963f7cfd21503497d1e68c4bfa61464ffb/phabricator/webroot/rsrc/_cache2.php:4\nStack trace:\n#0 {main}\n thrown in /srv/deployment/phabricator/deployment-cache/revs/22fcde963f7cfd21503497d1e68c4bfa61464ffb/phabricator/webroot/rsrc/_cache2.php on line 4
I do not know what that file is; maybe someone was just live-debugging? :)

brennen moved this task from To Triage to Infrastructure on the Phabricator board.

There's followup work to be done in improving the setup checks upstream and digging into repo caching, but the proximate problem seems resolved after tuning the APCu cache.

Note that despite apc.shm_size being set to 4096M, the UI shows it as:

Memory Usagex% of 3 GB

If I create a /srv/deployment/phabricator/deployment/phabricator/webroot/rsrc/cache.php with:

<?php
var_export( apcu_sma_info(), 1 );

I get:

array(4) {
  ["num_seg"]=>
  int(1)
  ["seg_size"]=>
  float(4294967176)
  ["avail_mem"]=>
  float(3584644424)

Note how 4294967176 is wrong. 4 x 1024³ is 4294967296. Thus the APC segment size is 120 bytes shorter than the requested 4G.

Phabricator code sets the cache total memory using:

$this->setTotalMemory($mem['num_seg'] * $mem['seg_size']);

Formats it with:

phutil_format_bytes($mem_total)));

Which uses https://www.php.net/floor which rounds to inferior integer:

function phutil_format_units_generic(
...
  if ($precision) {
    $num_string = number_format($n, $precision);
  } else {
    $num_string = (int)floor($n);
  }

Thus we get:

php > $n = 4294967176 / 1024 / 1024 / 1024 

php > var_dump(  $n );
double(3.999999888241291)

php > var_dump( floor( $n ) );
double(3)

php > var_dump( (int)floor( $n ) );
int(3)

Thus Phabricator displaying a maximum size of 3G is a presentation artifact and the cache is properly set to 4G.

@hashar: Uh, thanks for digging into that. I guess one of us should file an upstream bug report about that? (Do you want me to do that?)

@hashar: Uh, thanks for digging into that. I guess one of us should file an upstream bug report about that? (Do you want me to do that?)

Yes I think the display issue should be addressed, it probably does not matter for sizes in MB, but a 1G allocation might end up showing as 0 (cause 1 * 1024^3 - 120 = 0.xxxx which would be rounded down to 0? and well 3 is not 4 which I found surprising and I wanted to make sure it was "just a display glitch".

Please file it for me, you get more experience with phorge than me and I am unlikely to be able to follow up with upstream :]

Change #1191747 had a related patch set uploaded (by Dzahn; author: Dzahn):

[operations/puppet@production] phabricator: hiera'ize the apc_shm_size variable

https://gerrit.wikimedia.org/r/1191747

Change #1191747 merged by Dzahn:

[operations/puppet@production] phabricator: hiera'ize the apc_shm_size variable

https://gerrit.wikimedia.org/r/1191747

phab test instance is now configured to 256M and puppet is enabled again