That's roughly ~80% of all of the writes on mainstash at the moment.

It's clearly writing the same value over and over again:

> var_dump( $mainstash);
string(491) "{"paths":["extensions/WikimediaBadges/resources/skins/../images/badge-digitaldocument.png","extensions/WikimediaBadges/resources/skins/../images/badge-golden-star.png","extensions/WikimediaBadges/resources/skins/../images/badge-problematic.png","extensions/WikimediaBadges/resources/skins/../images/badge-proofread.png","extensions/WikimediaBadges/resources/skins/../images/badge-silver-star.png","extensions/WikimediaBadges/resources/skins/../images/badge-validated.png"],"asOf":1741564576}"

> $mainstash = \MediaWiki\MediaWikiServices::getInstance()->getMainObjectStash()->get( 'enwiki:ResourceLoaderModule-dependencies:ext.wikimediaBadges|vector-2022|en');

> var_dump( $mainstash);
string(491) "{"paths":["extensions/WikimediaBadges/resources/skins/../images/badge-digitaldocument.png","extensions/WikimediaBadges/resources/skins/../images/badge-golden-star.png","extensions/WikimediaBadges/resources/skins/../images/badge-problematic.png","extensions/WikimediaBadges/resources/skins/../images/badge-proofread.png","extensions/WikimediaBadges/resources/skins/../images/badge-silver-star.png","extensions/WikimediaBadges/resources/skins/../images/badge-validated.png"],"asOf":1741566101}"

> $mainstash = \MediaWiki\MediaWikiServices::getInstance()->getMainObjectStash()->get( 'enwiki:ResourceLoaderModule-dependencies:ext.wikimediaBadges|vector-2022|en');

> var_dump( $mainstash);
string(491) "{"paths":["extensions/WikimediaBadges/resources/skins/../images/badge-digitaldocument.png","extensions/WikimediaBadges/resources/skins/../images/badge-golden-star.png","extensions/WikimediaBadges/resources/skins/../images/badge-problematic.png","extensions/WikimediaBadges/resources/skins/../images/badge-proofread.png","extensions/WikimediaBadges/resources/skins/../images/badge-silver-star.png","extensions/WikimediaBadges/resources/skins/../images/badge-validated.png"],"asOf":1741566906}"

(note the asOf)

Maybe related maybe not, the hit rate ratio for ResourceLoaderModule-dependencies is 26% (around 1M times every minute) which is clearly not normal: https://grafana.wikimedia.org/d/4plhqSPGk/bagostuff-stats-by-key-group?orgId=1&var-kClass=ResourceLoaderModule_dependencies

I will debug this further. This clearly needs fixing ASAP.

Another data point: Out of all the writes I went through (99K), 78K were the RL dep updates and out of those 61K (77% or 61% of total) are just updating of dependencies of ext.wikimediaBadges across different wikis. It might be because that RL module is called on everything or it might be that something is broken about that RL module. I'm still investigating (sorry my MO is to just brain dump as I go).

13K more writes (totaling 94%) are ext.uls.pt. Both have skinStyles https://gerrit.wikimedia.org/g/mediawiki/extensions/WikimediaBadges/+/867ee90d060d2f895d2497ce3077a89a3b2a9d53/extension.json#23 and https://gerrit.wikimedia.org/g/mediawiki/extensions/UniversalLanguageSelector/+/03807fd207a832ae46551145822931a64ad638b8/extension.json#305

I have a feeling any RL module that uses skinStyles is having a fun time with x2

Okay my hypothesis right now is this:

Wikimedia Badges has this defintion for the RL module:

	"ResourceModules": {
		"ext.wikimediaBadges": {
			"skinStyles": {
				"vector": "skins/vector/wikimedia-badges.css",
				"vector-2022": "skins/vector/wikimedia-badges.css",
				"monobook": "skins/monobook/wikimedia-badges.css",
				"cologneblue": "skins/cologneblue/wikimedia-badges.css",
				"modern": "skins/modern/wikimedia-badges.css"
			}
		}
	},

You notice that no dependency have been mentioned. But the value I mentioned above says this RL module has dependencies: T388323#10616898 which seems to be coming from them being declared implicitly in the js code: https://gerrit.wikimedia.org/r/plugins/gitiles/mediawiki/extensions/WikimediaBadges/+/867ee90d060d2f895d2497ce3077a89a3b2a9d53/resources/skins/vector/wikimedia-badges.css

Maybe I'm missing something obvious but let me dig deeper.

Yup, *I think* the reason seems to be undeclared image causing this: https://gerrit.wikimedia.org/r/plugins/gitiles/mediawiki/extensions/UniversalLanguageSelector/+/03807fd207a832ae46551145822931a64ad638b8/resources/css/ext.uls.pt.less

Let me properly declare it for the badges (given that it should be done regardless it's the source of this bug or not: https://www.mediawiki.org/wiki/Manual:ResourceLoaderImageModule.php), get it deployed ASAP and then see if it makes a difference.

Change #1126120 had a related patch set uploaded (by Ladsgroup; author: Amir Sarabadani):

[mediawiki/extensions/WikimediaBadges@master] Declare image dependencies

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

Change #1126127 had a related patch set uploaded (by Bartosz Dziewoński; author: Bartosz Dziewoński):

[mediawiki/core@master] FileModule: Normalize file paths for deps tracked from CSSMin

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

Change #1126120 abandoned by Ladsgroup:

[mediawiki/extensions/WikimediaBadges@master] Declare image dependencies

Reason:

Different approach

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

Change #1126129 had a related patch set uploaded (by Ladsgroup; author: Bartosz Dziewoński):

[mediawiki/core@wmf/1.44.0-wmf.19] FileModule: Normalize file paths for deps tracked from CSSMin

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

Key insight from IRC discussion:

[19:24]	<MatmaRex> in Module::saveFileDependencies(), we store if there are differences between $paths and $priorPaths
[19:24]	<MatmaRex> so i added some debug logging, and
[19:25]	<MatmaRex> one of them has paths like this:
[19:25]	<MatmaRex> extensions/WikimediaBadges/resources/skins/../images/badge-silver-star.png
[19:25]	<MatmaRex> and the other:
[19:25]	<MatmaRex> extensions/WikimediaBadges/resources/images/badge-silver-star.png

The paths ultimately come from $this->localFileRefs in FileModule, there are two places that write to that field; one of them normalized the paths already, but the other did not.

Change #1126129 merged by jenkins-bot:

[mediawiki/core@wmf/1.44.0-wmf.19] FileModule: Normalize file paths for deps tracked from CSSMin

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

Mentioned in SAL (#wikimedia-operations) [2025-03-10T19:03:46Z] <ladsgroup@deploy2002> Started scap sync-world: Backport for [[gerrit:1126129|FileModule: Normalize file paths for deps tracked from CSSMin (T388323)]]

Mentioned in SAL (#wikimedia-operations) [2025-03-10T19:06:30Z] <ladsgroup@deploy2002> ladsgroup: Backport for [[gerrit:1126129|FileModule: Normalize file paths for deps tracked from CSSMin (T388323)]] synced to the testservers (https://wikitech.wikimedia.org/wiki/Mwdebug)

Mentioned in SAL (#wikimedia-operations) [2025-03-10T19:14:39Z] <ladsgroup@deploy2002> Finished scap sync-world: Backport for [[gerrit:1126129|FileModule: Normalize file paths for deps tracked from CSSMin (T388323)]] (duration: 10m 53s)

https://grafana.wikimedia.org/d/4plhqSPGk/bagostuff-stats-by-key-group?orgId=1&var-kClass=ResourceLoaderModule_dependencies&from=1741631073644&to=1741634651497

And

Thank you! @matmarex do you want to keep it open for future changes?

In T388323#10620741, @Ladsgroup wrote:

Thank you! @matmarex do you want to keep it open for future changes?

Yes, the patch is not merged into master yet, @Krinkle said he's reviewing it.

Change #1126515 had a related patch set uploaded (by Ladsgroup; author: Bartosz Dziewoński):

[mediawiki/core@wmf/1.44.0-wmf.20] FileModule: Normalize file paths for deps tracked from CSSMin

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

Change #1126515 merged by jenkins-bot:

[mediawiki/core@wmf/1.44.0-wmf.20] FileModule: Normalize file paths for deps tracked from CSSMin

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

Mentioned in SAL (#wikimedia-operations) [2025-03-11T11:50:26Z] <ladsgroup@deploy2002> Started scap sync-world: Backport for [[gerrit:1126515|FileModule: Normalize file paths for deps tracked from CSSMin (T388323)]]

Mentioned in SAL (#wikimedia-operations) [2025-03-11T11:55:26Z] <ladsgroup@deploy2002> ladsgroup: Backport for [[gerrit:1126515|FileModule: Normalize file paths for deps tracked from CSSMin (T388323)]] synced to the testservers (https://wikitech.wikimedia.org/wiki/Mwdebug)

Mentioned in SAL (#wikimedia-operations) [2025-03-11T12:04:08Z] <ladsgroup@deploy2002> Finished scap sync-world: Backport for [[gerrit:1126515|FileModule: Normalize file paths for deps tracked from CSSMin (T388323)]] (duration: 13m 41s)

Given the load that this represents, should it be UBN! until merged into master (outstanding) and prod (currently done)?

Change #1127058 had a related patch set uploaded (by Hokwelum; author: Hokwelum):

[RelPath@master] Fix multiple sub path

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

Change #1127713 had a related patch set uploaded (by Krinkle; author: Krinkle):

[RelPath@master] tests: Add test cases

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

Change #1127713 merged by jenkins-bot:

[RelPath@master] tests: Add test cases

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

Change #1127058 merged by jenkins-bot:

[RelPath@master] Fix getRelativePath() with multiple ".." parent fragments

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

Summary of what was causing this bug:

The function handling the normalization wasn’t handling multiple ../, what this means is that for example;

Let’s say on the first load, a dependency like extensions/WikimediaBadges/resources/skins/vector/../../images/badge-silver-star.png is saved as extensions/WikimediaBadges/resources/skins/../images/badge-silver-star.png.

On the next call, we compare the already saved dependency with the dependency found by less parser if any new dependencies need to be saved. In this case, we still see extensions/WikimediaBadges/resources/skins/vector/../../images/badge-silver-star.png as a dependency found which is still reduced to extensions/WikimediaBadges/resources/skins/../images/badge-silver-star.png same as before, but this time around, the saved dependency has again been reduced to extensions/WikimediaBadges/resources/images/badge-silver-star.png.

Here are a few things to note:

• The new dependency is normalized once using getRelativePath.
• The saved dependency is normalized twice—first before saving, and again after retrieving it. This happens because we expand the path, and then call RelPath::getRelativePath on the expanded path before comparison.
• Since the normalization function could only handle one ../ pair at a time, roundtripping twice resulted in inconsistencies.

As a result, comparing WikimediaBadges/resources/skins/../images/badge-silver-star.png (new value) with WikimediaBadges/resources/images/badge-silver-star.png (saved value) caused them to be treated as different dependencies, and unnecessarily saves duplicate entries in the database.

This has now been fixed by fully normalizing paths before comparison, ensuring multiple ../ are resolved consistently.

Change #1127997 had a related patch set uploaded (by Hokwelum; author: Hokwelum):

[RelPath@master] Tag 4.0.2

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

Change #1127997 merged by jenkins-bot:

[RelPath@master] Tag 4.0.2

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

Change #1128010 had a related patch set uploaded (by Hokwelum; author: Hokwelum):

[mediawiki/vendor@master] update wikimedia/relpath to 4.0.2

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

Change #1128011 had a related patch set uploaded (by Hokwelum; author: Hokwelum):

[mediawiki/core@master] ResourceLoader: Update wikimedia/relpath to 4.0.2

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

Change #1128010 merged by jenkins-bot:

[mediawiki/vendor@master] update wikimedia/relpath to 4.0.2

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

Change #1128011 merged by jenkins-bot:

[mediawiki/core@master] ResourceLoader: Update wikimedia/relpath to 4.0.2

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

Change #1126127 abandoned by Bartosz Dziewoński:

[mediawiki/core@master] FileModule: Normalize file paths for deps tracked from CSSMin

Reason:

This workaround is no longer needed, as the root cause of the problem was found.

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

In T388323#10620087, @Ladsgroup wrote:

[…] no dependency have been mentioned. But the value I mentioned above says this RL module has dependencies […] declared implicitly in the code: […]

In T388323#10620140, @Ladsgroup wrote:

Yup, *I think* the reason seems to be undeclared image causing this: […]

Let me properly declare it for the badges […]

To circle back here, there are no "declared" or "undeclared" images in ResourceLoader.

The way to express that a Less stylesheet imports a file, or that a CSS stylesheet references an image, is to do precisely that. We offer no way to, and indeed developers don't need to, separately list these out in a second place. (It was mentioned in CR already, but for visiblity: The extension.json fields you found relate to the opposite use case where e.g. OOUIIconPackModule generates icon CSS. In those cases, there are no CSS files. The JSON generates that CSS. For most stylesheets it is the other way around: You write the CSS and we discover the image references).

The place where ResourceLoader declares such indirect dependencies, is in the DependencyStore (via MainStash), which is the database table that this task is about. We "remember" these dependencies from past builds, so that the Startup module can efficiently do large-scale version hashing and change detection for 1000 modules with low latency response times (as opposed to re-building/compiling each to rediscover them).

In T388323#10616898, @Ladsgroup wrote:

That's roughly ~80% of all of the writes on mainstash at the moment.

It looks like the WikimediaBadges extension has used the ../../ pattern since at least 2018. I presume some time prior to that, when it was first deployed, rates sharply increased to 2000 writes/s overnight, due to the path normalization bug. The 2020 data at T229062#6186134, confirms these 2000 write/s were included in and part of our "normal" write rate on Redis.

While 2000 writes/s seems within our capacity to support (noting that MainStash DB was provisioned with these numbers in mind, and we have other clusters with higher write rates), there is no doubt that this puts x2 among the top 5 most-busy clusters, and we now know that it turns out it doesn't need to be that way at all. Looking at host metrics for db2142 and db1152 (x2 masters in codfw/eqiad), I was expecting to see a drop there in CPU, Mem, Disk, or Network. But, it seems those hosts are (from their provisioned perspective) relatively idle and unmoved by our fix rolling out. That's... surprising?

In short: This fix solved an absolutely gross inefficiency that needlessly inflated 75 writes/s to 2000 writes/second. We were well-provisioned for this, and have operated this way unnoticed for several years.

I suspect my summary so far is nothing new or disagreeable. The urgency on this task came not from the write rate we have today, but from the fear of where it might grow to during the next heavy load event from e.g. a celebrity death.

[…] This clearly needs fixing ASAP.

I've discussed this on IRC already, but I'll summarise here for @Jdforrester-WMF and others benefit.

I believe this fear is misplaced because the kind of traffic scale increases we see on MediaWiki webservers for pageviews fundamentally does not apply to ResourceLoader:

1. Finite and mostly-static set of resources with deterministic URLs.
2. No logged-in user cache bypass, and no HTTP purges (thus ideal for request coalescing).
3. > 99.98% Varnish cache-hit rate.
4. Failsafe: Zero concurrency for database writes about the same resource.

The backend request rate for endpoints like ResourceLoader do not increase much from external demand or other traffic spikes. This is because for a given resource, only ~1 request is needed to the backend during a given cache expiry window (e.g. 5 minutes, 1 hour, or 30 days). That backend request will happen so long as there is at least 1 person demanding the resource during that time window. Any additional demand is absorbed at the edge. And only when that demand drops to absolute 0 for the entire duration would that request not happen. Let's say hypothetically that during the German nightime, pageviews on de.wikipedia.org pageviews drop from millions per minute to a few hundred per minute. So long as there's at least one, the same resources will keep being fed to the cache. There will be some reduction, i.e. there might be a few minutes of 0 hits to certain skin or language variants during the night, but that difference is small and comes from a finite set that we can grow/explore.

For pageviews, there is a long tail of user-generated pages (i.e. "cold" content) that can start to be explored, plus constant edits/purging. Both of which increase when more people are online. The long tail grows into cold pages, or entirely new revisions/edits, more backend requests. Plus we have logged-in users bypassing the cache on top of that.

For load.php, we see a near-constant backend load, based on the number of unique resources requested in a given time window. Noting that there are no purges. Even for narrow case of on-wiki user-editable gadgets, these roll out at the fixed next 5-min interval for the startup module. ResourceLoader frontend requests (measured at Varnish), using last week as example, show a fairly predictable daily seasonality (peaks around 46K/s at 14:00 UTC, and bottoms out around 25K/s at 05:00 UTC). That's a 20,000/s increase, nearly doubling the traffic depending on the time of day:

Yet, for the ResourceLoader backend, the request rate remains at a fairly constant ~250 requests per second, all day any day.

That binlog I checked span through 2012 seconds (roughly half an hour) and in duration of half an hour enwiki:ResourceLoaderModule-dependencies:ext.wikimediaBadges|vector-2022|en key got written into 16,430 times.

At Grafana dashboard: ResourceLoader module builds we can see that ext.wikimediaBadges is rebult on the backend about 50 times per second:

In other words, of the 250, about 50 are for the wiki's main stylesheet bundle with various skin and extension modules (including ext.wikimediaBadges). Those 50 are for different (wiki, skin, language) combinations taking turns to reach their respective 30min max-age expiry. Looking even more closely via kafkacat/webrequest_text I see that a majority of these cache misses last week were actually from some kind of security scanner constructing novel URLs that append bogus like sql=SELECT+* and such to URLs, which explains the increase in backend request. However, note that these do not translate into an increase in database writes, since we only write when data changes, and on top of that, there is a failsafe that enforces zero concurrency.

This failsafe is a hard throttle in ResourceLoader that never save dependencies (i.e. write to MainStash) if another request is doing so for the same module already. This means that even if everything is broken (Varnish request coleascing fails, and large numbers of users hit the MediaWiki backends for load.php, and we have a bug that wrongly detects change when there is none) the database write rate still naturally throttles to meet whatever latency and load we can support. The failsafe is implemented as a non-blocking lock in Memcached (timeout=0) which immediately yields and skips over this write if there is any concurrency (PoolCounter permits upto 1-3 concurrent requests, ResourceLoader permits 0).

This binlog write rate (16430/2012) translates to ~8 per second for module=ext.wikimediaBadges with skin=vector-2022&lang=en, which is a subset that comes from a larger set of requests that may have been ocurring during those seconds. Prior the "change detection" bug being fixed, that still meant only 1 request at any given moment was given the greenlight to perform a write. If the writes were to slow down for any reason, that number would decrease along with it. In this case, it has a lot of headroom before that would happen since the writes take ~1-5ms and that would need to increase a lot before the failsafe kicks in to reduce it below 8/s.

In T388323#10647763, @Krinkle wrote:

In short: This fix solved an absolutely gross inefficiency that needlessly inflated 75 writes/s to 2000 writes/second. But, we were well-provisioned for this, and have operated this way unnoticed for several years.

This is one way to put it. Another way is that we made storage decisions and sizing based on that write rate. So yeah, this isn't just a gross inefficiency, it's an inefficiency we've had to plan around, because we know how to do our jobs.

I suspect my summary so far is nothing new or disagreeable. The urgency on this task came not from the write rate we have today, but from the fear of where it might grow to during the next heavy load event from e.g. a celebrity death.

Without going through the rest of your summary, your assumpition here is wrong: the urgency is because a storage system receiving 75 writes/s is orders of magnitude easier to manage operationally than one that does 2k writes/s, from a myriad of points of view. The urgency is given by the fact a simple one-line change allowed us to make a system more manageable for DBAs.

So.... I was wondering how it could be that 250/s MW backend requests, that made at most 1 write each, how could that possibly have translated into 2000 write/s? It turns out... they never did.

I used a bad metric that was off by two orders of magnitude. This is my fault, because I looked at the MySQL Aggregated dashboard, and failed to consider how this isn't what it seems. That dashboard double counts in various ways (sums 3 independent counters update+delete+write together from a single "update" sql command, and further sums replication to 3 standby hosts which is not unusual except that MainStash and ParserCache don't recognise replicas in MW, and I forgot we have (and include) our "shadow" replicas here).

Here's what we show on Grafana: mysql-aggregated by default:

And here's what you see if you edit it to break down the sum:

This matches Amir's original numbers as well. Note that the below are totals from a half-hour sample:

From the task description:

16,430 writes in 2012 seconds (roughly half an hour) for enwiki:ResourceLoaderModule-dependencies:ext.wikimediaBadges|vector-2022|en

From T388323#10619602:

[Out of half hour of] writes I went through (99K), 78K were the RL dep updates […]

That's 43/s in total, before the fix. Not 2000/s. Of which 8/s were for the "ext.wikimediaBadges" key, which was the most common one in the sample.

This also matches the Statsd counters from MediaWiki MainStash (two DCs, together 80/s to 1/s):

And the MySQL per-host stats (100/s to 20/s), which include writes from Parsoid and other x2 consumers:

Change #1137846 had a related patch set uploaded (by Krinkle; author: Hokwelum):

[mediawiki/core@master] ResourceLoader: Refactor getFileDependencies to return relative file paths

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

Change #1137846 merged by jenkins-bot:

[mediawiki/core@master] ResourceLoader: Refactor getFileDependencies to return relative file paths

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