Mentioned in SAL (#wikimedia-operations) [2022-06-14T17:12:58Z] <brennen> train 1.39.0-wmf.16 (T308069): train is blocked - will sync to testwikis and hold there for resolution of T310532

In case it's helpful here, here's a list of everything that went live during that spike: https://www.mediawiki.org/wiki/MediaWiki_1.39/wmf.15/Changelog

It would narrow it down to know what these additional requests were for—how can I find that information? Only in Hive? Or can I find it elsewhere? (I realize I don't have access to Hive).

Is this just the UBN-ness of the back-ported fixes to AbuseFilter for T212129: Move MainStash out of Redis to a simpler multi-dc aware solution?

No, because it's still apparent in prod after that was back-ported. Never mind.

1.39.0-wmf.15 code stuff

In T310532#8004202, @Jdforrester-WMF wrote:

Is this just the UBN-ness of the back-ported fixes to AbuseFilter for T212129: Move MainStash out of Redis to a simpler multi-dc aware solution?

No, because it's still apparent in prod after that was back-ported. Never mind.

Is this using redis and/or sql? Would this account for an increase in mcrouter GET requests? @tstarling ?

Other changes from last week that mention (cache|sqlblob|wanob)

• (seems innocuous but touches things stored in memcached) https://gerrit.wikimedia.org/r/c/mediawiki/extensions/Translate/+/802136 @ihurbain
• A few for changes for resourceloader: unclear if that touches this system anywhere @Krinkle

Finding more information stuff

In T310532#8004092, @thcipriani wrote:

In case it's helpful here, here's a list of everything that went live during that spike: https://www.mediawiki.org/wiki/MediaWiki_1.39/wmf.15/Changelog

It would narrow it down to know what these additional requests were for—how can I find that information? Only in Hive? Or can I find it elsewhere? (I realize I don't have access to Hive).

I looked at web traffic on the localhost of an appserver: no increase in traffic before vs after deploy to account for this. So something in the application is doing more GET requests to memcached independent of traffic.

@JMeybohm Is the increase in requests an increase for any particular key? How would I find that information? Is there a dashboard? Can I grep a thing?

Meeting with Krinkle, Aaron, we think it's because a recent change to zh fallbacks caused the MessageCache MapCacheLRU size to be exceeded, causing a reload of the MessageCache keys on every message instead of once per request.

I'm working on a patch.

Change 805497 had a related patch set uploaded (by Tim Starling; author: Tim Starling):

[mediawiki/core@master] Increase MessageCache MapCacheLRU size

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

Here goes. Let's start with the actual source of the alert.

https://grafana.wikimedia.org/d/RIA1lzDZk/application-servers-red-dashboard?orgId=1&from=1654530600000&to=1654876200000&viewPanel=26

This is from the "Application RED" dashboard, and plots memc traffic stats as observed from the appserver-local mcrouter proxy.

Let's start by confirming correlation to the train.

The spike is extremely immediate, taking a single minute to double the request rate, and has sustained throughout the days since. If it weren't that steep a spike, I would have opened the graph editor to see if it got smoothed out by a moving average (e.g. by incorrectly using rate[5m], instead of irate[5m]).

From 18:54-18:56 UTC:

From https://sal.toolforge.org/production?p=1&q=&d=2022-06-09

• (18:56) rebuilt and synchronized wikiversions files: all wikis to 1.39.0-wmf.15 refs T308068

Next up, looking at the breakdown of memcached keys to see if we can pinpoint what MediaWiki component (docs: Memcached at WMF). These stats are provided by the WANObjectCache abstraction layer.

https://grafana.wikimedia.org/d/2Zx07tGZz/wanobjectcache?orgId=1&from=1654560000000&to=1654905599000

This is suspiciously stable. That's the first sign of something unusual happening here. One thing that comes to mind is that perhaps the cache keys responsible for the doubling are bypassing our WANCache interface? This is very unusual, but possible. (docs: MediaWiki cache interfaces). See also the diagram at wikitech: Memcached for MediaWiki, which shows two or three core features bypassing the WANCache layer and its stats.

As a first pass to look for anything obvious that might have broken our Memcached interactions, I looked at the wmf.15 branch change log (https://www.mediawiki.org/wiki/MediaWiki_1.39/wmf.15). Looking for anything relating to objectcache, cache, purge, memc, wancache, expiry, etc. Nothing stood out however.

To confirm that hypothesis, and to figure out what cache keys are actually responsible, I ran memkeys on one of the servers. I initially checked this on a random memc host, and there the following key stood out as being at least twice as common as the second most key during the 60 second capture.

krinkle@mc1046:~$ sudo memkeys -i ens2f0np0

WANCache:zhwiki:messages:en|#|t    …
…

One thing of note here, it took me a while to get memkeys to work because last time I used this (~1 year ago?) I ran it as sudo memkeys -i eth0, but that found not such network interface. As per ifconfig, it looks like ens2f0np0 is name of the network interface these days. I'm guessing this is something that changed either in a hardware refresh or as part of a newer Debian version.

I couldn't really tie this to much though, and the wiki-id distribution in the memc traffic didn't look right or representive. I then ran this on an mw appserver instead, to get a more representative sample of the outgoing memc traffic (instead of the incoming traffic on a single memc shard).

krinkle@mw1393:~$ sudo memkeys -i lo -p 11213

memcache key                                                      calls
WANCache:zhwiki:messages:en:hash:v1|#|v                           3525 
WANCache:zhwiki:messages:zh-hant:hash:v1|#|v                      3486 
WANCache:zhwiki:messages:zh-hk:hash:v1|#|v                        3469 
WANCache:zhwiki:messages:zh-hans:hash:v1|#|v                      3466 
WANCache:zhwiki:messages:zh-tw:hash:v1|#|v                        3463 
WANCache:zhwiki:messages:zh-cn:hash:v1|#|v                        3385 
WANCache:zhwiki:messages:zh:hash:v1|#|v                           3347 
WANCache:enwiki:pageimages-denylist|#|v                           784
…
WANCache:enwiki:messages:en:hash:v1|#|v                           404
WANCache:global:revision-row-1.29:enwiki:…
WANCache:global:rdbms-server-readonly:¬
WANCache:global:resourceloader-titleinfo:…
WANCache:enwiki:sidebar:en|#|v        …
WANCache:zhwikibooks:messages:zh:hash:v1|#|v                      75
WANCache:zhwikibooks:messages:en:hash:v1|#|v                      75
WANCache:zhwikibooks:messages:zh-tw:hash:v1|#|v                   74
WANCache:zhwikibooks:messages:zh-hans:hash:v1|#|v                 74
WANCache:zhwikibooks:messages:zh-hant:hash:v1|#|v                 74
WANCache:zhwikibooks:messages:zh-cn:hash:v1|#|v                   74

@tstarling and @aaron thought that perhaps this is due to the value being too big to be written to Memc. To verify this, we looked at whether the "set" traffic is increased was well. It was not.

We also looked at whether perhaps Mcrouter is depooling an entire memc host as a result of that or other write failures. To verify this, we looked at the Grafana: Memcache dashboard to see if at the backend memcache level, traffic was in fact similarly elevated. In other words, are the mcrouter "gets" actually making it to the memcache backends? They were, there was no dip in traffic on memcache backends not an increase in sets.

This brings us back to the application level.

@tstarling mentions debug logs (docs: WikimediaDebug). We can enable verbose logging for a zhwiki page view, and see what happens. Answering the following questions:

• Is MW logging an error at all, of any kind? No, there were not. Memcached did not report errors as seen by the MW level.
• For other web requests (looking at "Logstash: mediawiki-warnings" more broadly for the past 7 days), we do see a background level of "TOO BIG" errors from Memc, but nothing more than the usual amount, with a few spikes here and there, but nothing sustained for the past 7 days that wasn't there before.
• Is MW requesting multiple of these memc zh-variant keys during the same web request? Yes, the same reqId of my mwdebug request, was doing mutiple of the above. In fact, it's requesting the exact same key, over one hundred times.

Jun 14, 2022 @ 23:32 DEBUG MessageCache zhwiki

MessageCache::load: Loading zh-hk... got from local cache
MemcachedPeclBagOStuff debug: getMulti(WANCache:zhwiki:messages:en:hash:v1|#|v, WANCache:zhwiki:messages:en|#|t)
MemcachedPeclBagOStuff debug: getMulti(WANCache:zhwiki:messages:zh:hash:v1|#|v, WANCache:zhwiki:messages:zh|#|t)
MessageCache::load: Loading en... got from local cache
MemcachedPeclBagOStuff debug: getMulti(WANCache:zhwiki:messages:zh-hans:hash:v1|#|v, WANCache:zhwiki:messages:zh-hans|#|t)
MessageCache::load: Loading zh... got from local cache
MessageCache::load: Loading zh-hans... got from local cache
MemcachedPeclBagOStuff debug: getMulti(WANCache:zhwiki:messages:zh-hant:hash:v1|#|v, WANCache:zhwiki:messages:zh-hant|#|t)
MessageCache::load: Loading zh-hant... got from local cache
MemcachedPeclBagOStuff debug: getMulti(WANCache:zhwiki:messages:zh-cn:hash:v1|#|v, WANCache:zhwiki:messages:zh-cn|#|t)
MemcachedPeclBagOStuff debug: getMulti(WANCache:zhwiki:messages:zh-tw:hash:v1|#|v, WANCache:zhwiki:messages:zh-tw|#|t)
MessageCache::load: Loading zh-cn... got from local cache
MemcachedPeclBagOStuff debug: getMulti(WANCache:zhwiki:messages:zh-hk:hash:v1|#|v, WANCache:zhwiki:messages:zh-hk|#|t)
MessageCache::load: Loading zh-tw... got from local cache
MessageCache::load: Loading en... got from local cache
MessageCache::load: Loading zh-hk... got from local cache
MemcachedPeclBagOStuff debug: getMulti(WANCache:zhwiki:messages:en:hash:v1|#|v, WANCache:zhwiki:messages:en|#|t)
MemcachedPeclBagOStuff debug: getMulti(WANCache:zhwiki:messages:zh:hash:v1|#|v, WANCache:zhwiki:messages:zh|#|t)
…repeat...

This combined with the fact that there are no errors, means the MessageCache class must be doing this multiple times for some reason. Not only are there no error messages from the memcached level, there are in fact "success" message from the MessageCache class. The got from local cache message means it reached the $success = true;'` code path around mediawiki-core: MessageCache.php:L326, and thus marking the language as "loaded". And so there'd be no reason to load it again when the next interface message string is rendered.

At this point, I took another look at the wmf.15 Changelog page. This time looking for message, locali, zh. And... yep:

git #934c9226 - Rearrange zh-related language fallback chain (task T286291) (task T296188) (task T252367) (task T278639) by Winston Sung
https://gerrit.wikimedia.org/r/c/mediawiki/core/+/703560

The change looks suspicious in a number of ways, and is certainly significant. For one, it's the first time (I think?) that were adding fallback from other zh variants to the main zh stub, and also quite a lot of fallbacks that seem potentially redundant. Based on very limited knowledge of how LanguageConverter is used, and the fact that a number of zh- languages have their own wiki, it seems certainly non-obvious that that many fallbacks are desirable from an end-user perspective to be mixed onto a single page view and meshed together. But.. I'm assuming for now that the change was done either through a community request or at least with consensus from editors and translators, and certainly tested to a basic extent locally, and later in Beta or in prod during the past week.

Back to the perf issue for now. The only way that MapCacheLRU $cache->set() can return success and then almost immediately fail again, is... if it got evicted. That's not supposed to happen under normal circumstances. The limit is mainly there to protect against jobs, CLI scripts, and rare batch actions running out of memory from holding on to stuff that was only briefly needed.

class MessageCache {
		$this->cache = new MapCacheLRU( 5 );
}

And from the above change:

- $fallback = 'zh-hans';
+ $fallback = 'zh-hans, zh-hant, zh-cn, zh-tw, zh-hk';

That's 1, 2, 3, 4, 5, plus zh itself makes 6, plus en as source fallback makes 7. 7 is more than 5. Ergo, throughout the page view, we're looping through and.. "mopping the floor while the tap is running", as we say in Dutch.

My gut says it's okay to raise this limit since most notabley this limit is not the LocalisationCache/LanguageFactory limit, which is responsible for a bigger memory payload (the MessageCache is only the light layer over top LC for on-wiki overrides from NS_MEDIAWIKI pages). And there are generally relatively few overrides. And we already exclude "big" messages from the MessageCache blob, to be fetched from their own APCu-cached key without an in-process copy.

For the most part, things were working correctly here.

• Mcrouter did not TKO the memc host.
• libmemcached/php-memcached did not depool Mcrouter.
• We did not stampede on sets or otherwise perceived any major cache misses.
• The memc-mw cluster network links did not saturate.
• The site stayed up!

As @tstarling mentioned during the retro at the end, though, we should definitely have at least a static error of sorts as this is an obvious and determinstic configuration error. It's totally fine to happen at run-time for one reason or another, but we can at least have a structure test in CI to catch when a language is explicitly defined to have more fallbacks than we can hold in-memory and deny that from being merged as-is. Possibly we can also send a warning message to Logstash in production if count(fallbacks) ends up larger than the MessageCache's LRU size constant.

Change 805435 had a related patch set uploaded (by Krinkle; author: Tim Starling):

[mediawiki/core@wmf/1.39.0-wmf.16] MessageCache: Increase the MapCacheLRU size

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

Change 805436 had a related patch set uploaded (by Krinkle; author: Tim Starling):

[mediawiki/core@wmf/1.39.0-wmf.15] MessageCache: Increase the MapCacheLRU size

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

Change 805497 merged by jenkins-bot:

[mediawiki/core@master] MessageCache: Increase the MapCacheLRU size

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

Change 805436 merged by jenkins-bot:

[mediawiki/core@wmf/1.39.0-wmf.15] MessageCache: Increase the MapCacheLRU size

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

Change 805435 merged by jenkins-bot:

[mediawiki/core@wmf/1.39.0-wmf.16] MessageCache: Increase the MapCacheLRU size

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

Mentioned in SAL (#wikimedia-operations) [2022-06-15T02:17:24Z] <tstarling@deploy1002> Synchronized php-1.39.0-wmf.15/includes/cache/MessageCache.php: T310532 (duration: 03m 29s)

Change 805501 had a related patch set uploaded (by Tim Starling; author: Tim Starling):

[mediawiki/core@master] Add structure test for Messages*.php files

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

Thanks much all. @Krinkle, that writeup is a thing of beauty and possibly should be taught as a class on debugging cache issues.

Seconding what @brennen said. This is a beautiful writeup.

Change 805501 merged by jenkins-bot:

[mediawiki/core@master] Add structure test for Messages*.php files

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

For the change to fallback chain:

• Should we consider separate the Special:MyLanguage fallback from the message fallback (for example, add a new variable to override the $fallback for Special:MyLanguage) and reduce the message fallback cost (as it would no longer need to add so much code to the message fallback list)?
• What kind of way should we do for better "LanguageConverter <=> without LanguageConverter" content handling, including news feed to Village Pumps?