Page MenuHomePhabricator
Create Task
Maniphest T406170

Metric anomaly in resourceloader_build_seconds after 26 June 2025
Closed, ResolvedPublic
Actions

Description

I'm monitoring server load when enabling unified mobile routing on the largest wikis this and next week (T403510). I was expecting to see a temporary rise in ResourceLoader builds while we re-populate the CDN for mobile versions on the standard domain.

The Grafana dashboard claims that the "startup" module is built only 2-3 times per minute, whereas this is usually ~1000 per minute.

Screenshot 2025-10-01 at 11.22.16.png (1×2 px, 229 KB)

Zooming out shows that something broke around 26 June 2025. This suggests to me that this isn't a "real" change, but rather an issue with the instrumentation having (almost) stopped working.

https://grafana.wikimedia.org/d/000000067/resourceloader-module-builds?orgId=1&from=now-6M&to=now&timezone=utc&var-module=startup&viewPanel=panel-17

Screenshot 2025-10-01 at 11.20.46.png (1×2 px, 325 KB)

Details

Related Changes in Gerrit:
SubjectRepoBranchLines +/-
Stats: have RunningTimer manage the initial label setmediawiki/corewmf/1.45.0-wmf.25+23 -10
Stats: add getLabels() functionmediawiki/corewmf/1.45.0-wmf.25+14 -4
Stats: add getLabels() functionmediawiki/corewmf/1.45.0-wmf.24+14 -4
Stats: have RunningTimer manage the initial label setmediawiki/coremaster+23 -10
resourceloader: Use `setLabel()` after `start()` with recursive metricmediawiki/coremaster+2 -2
Stats: add getLabels() functionmediawiki/coremaster+14 -4
stats: restore stats recursion testsmediawiki/coremaster+43 -0
Customize query in gerrit

Related Objects

Event Timeline

Krinkle created this task.Oct 1 2025, 6:25 PM
Restricted Application added a project: MediaWiki-Platform-Team. · View Herald TranscriptOct 1 2025, 6:25 PM
Restricted Application added a subscriber: Aklapper. · View Herald Transcript
JTweed-WMF moved this task from Inbox, needs triage to Next (DO NOT USE) on the MediaWiki-Platform-Team board.Oct 13 2025, 2:33 PM
DAlangi_WMF subscribed.Oct 15 2025, 12:22 PM

Tracking down the train deployment for that week (wmf.7) led me to https://www.mediawiki.org/wiki/MediaWiki_1.45/wmf.7, and it appears that I merged a related patch: https://gerrit.wikimedia.org/r/c/mediawiki/core/+/1159547 that touches this metric.

I do not see how the patch could have broken that metric yet (I am still investigating), but that is the only match I can find for now. Locally (before and after), I can confirm that resourcealoader_build_seconds are still emitted, and I can see metrics related to the startup module too.

Krinkle added a comment.Oct 21 2025, 10:23 PM

@DAlangi_WMF I think that's the culprit indeed. That commit uses TimerMetric::start followed by TimerMetric::stop. This seems likely a case of T368073: TimingMetric and recursion edge case.

Does Module::buildContent recurse? I happen to know this, but this can be found emperically by debugging and detecting recursion or (if it doesn't happen locally, or you want a quicker answer) by looking at flame graphs from production.

https://performance.wikimedia.org/arclamp/svgs/daily/2025-10-20.excimer-wall.load.svgz?s=buildContent

StartupModule::buildContent calls Module::buildContent by way of getVersionHash. StartupModule doesn't recurse into itself, but it does (in one flat loop) call all other modules to compute their version hash. For modules that use Module::enableModuleContentVersion that means calling Module::buildContent. According to the flame graph, one example of that is VisualEditor.

LocalSetting
# $ socat -u UDP-RECVFROM:8125,fork,SO-RCVBUF=65536 -
$wgStatsTarget = 'udp://127.0.0.1:8125';
$wgStatsFormat = 'dogstatsd';

wfLoadExtension('VisualEditor');

http://localhost:4000/load.php?modules=startup&only=scripts&raw=1

…
mediawiki.resourceloader_build_seconds:2.731458|ms|#name:ext_visualEditor_data
mediawiki.resourceloader_build_seconds:58.686666|ms|#name:ext_visualEditor_data
…

Instead of reporting a timer for startup and one for ext_visualEditor_data, both are attributed to ext_visualEditor_data.

I suspect this is what happened in production as well.

gerritbot added a comment.Oct 24 2025, 5:12 PM

Change #1198571 had a related patch set uploaded (by D3r1ck01; author: Derick Alangi):

[mediawiki/core@master] resourceloader: Use `observe()` on with recursive timing metric

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

gerritbot added a project: Patch-For-Review.Oct 24 2025, 5:12 PM
DAlangi_WMF changed the task status from Open to In Progress.Oct 24 2025, 5:12 PM
DAlangi_WMF claimed this task.
DAlangi_WMF moved this task from Next (DO NOT USE) to In progress (DO NOT USE) on the MediaWiki-Platform-Team board.
gerritbot added a comment.Oct 27 2025, 5:43 PM

Change #1199036 had a related patch set uploaded (by Cwhite; author: Cwhite):

[mediawiki/core@master] stats: restore stats recursion tests

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

gerritbot added a comment.Oct 27 2025, 5:43 PM

Change #1199037 had a related patch set uploaded (by Cwhite; author: Cwhite):

[mediawiki/core@master] stats: add getLabels() function

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

gerritbot added a comment.Oct 27 2025, 5:43 PM

Change #1199038 had a related patch set uploaded (by Cwhite; author: Cwhite):

[mediawiki/core@master] stats: have RunningTimer set the labels

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

colewhite added a project: MediaWiki-libs-Stats.Oct 27 2025, 5:45 PM
gerritbot added a comment.Oct 27 2025, 6:43 PM

Change #1199036 merged by jenkins-bot:

[mediawiki/core@master] stats: restore stats recursion tests

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

ReleaseTaggerBot added a project: MW-1.45-notes (1.45.0-wmf.25; 2025-10-28).Oct 27 2025, 7:00 PM
gerritbot added a comment.Oct 29 2025, 1:44 AM

Change #1199037 merged by jenkins-bot:

[mediawiki/core@master] Stats: add getLabels() function

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

ReleaseTaggerBot added a project: MW-1.46-notes (1.46.0-wmf.1; 2025-11-05).Oct 29 2025, 2:00 AM
gerritbot added a comment.Oct 29 2025, 9:39 AM

Change #1198571 abandoned by D3r1ck01:

[mediawiki/core@master] resourceloader: Use `setLabel()` after `start()` with recursive metric

Reason:

Fixed properly in the stats framework in https://gerrit.wikimedia.org/r/c/mediawiki/core/+/1199038.

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

gerritbot added a comment.Oct 29 2025, 8:22 PM

Change #1199038 merged by jenkins-bot:

[mediawiki/core@master] Stats: have RunningTimer manage the initial label set

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

Maintenance_bot removed a project: Patch-For-Review.Oct 29 2025, 8:31 PM
gerritbot added a comment.Oct 29 2025, 8:39 PM

Change #1199854 had a related patch set uploaded (by D3r1ck01; author: Cwhite):

[mediawiki/core@wmf/1.45.0-wmf.25] Stats: add getLabels() function

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

gerritbot added a project: Patch-For-Review.Oct 29 2025, 8:39 PM

Change #1199856 had a related patch set uploaded (by D3r1ck01; author: Cwhite):

[mediawiki/core@wmf/1.45.0-wmf.25] Stats: have RunningTimer manage the initial label set

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

gerritbot added a comment.Oct 30 2025, 9:43 AM

Change #1200009 had a related patch set uploaded (by D3r1ck01; author: Cwhite):

[mediawiki/core@wmf/1.45.0-wmf.24] Stats: add getLabels() function

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

gerritbot added a comment.Oct 30 2025, 9:44 AM

Change #1200009 abandoned by D3r1ck01:

[mediawiki/core@wmf/1.45.0-wmf.24] Stats: add getLabels() function

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

gerritbot added a comment.Oct 30 2025, 8:03 PM

Change #1199854 merged by jenkins-bot:

[mediawiki/core@wmf/1.45.0-wmf.25] Stats: add getLabels() function

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

gerritbot added a comment.Oct 30 2025, 8:06 PM

Change #1199856 merged by jenkins-bot:

[mediawiki/core@wmf/1.45.0-wmf.25] Stats: have RunningTimer manage the initial label set

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

Maintenance_bot removed a project: Patch-For-Review.Oct 30 2025, 8:31 PM
DAlangi_WMF mentioned this in T408868: Log deployment activities on auto-detected changes during deployment.Oct 30 2025, 8:46 PM
DAlangi_WMF closed this task as Resolved.Oct 30 2025, 8:50 PM
DAlangi_WMF reassigned this task from DAlangi_WMF to colewhite.
DAlangi_WMF added a subscriber: colewhite.

Backports were deployed in https://wikitech.wikimedia.org/wiki/Deployments#deploycal-item-20251030T2000, but something interesting happened, and I filed T408868: Log deployment activities on auto-detected changes during deployment.

Also, I can confirm that the metrics are back up again, thank you @colewhite, I'll really assign this to you instead, as you really fixed the issue, and I only helped verify and code review. Extending thanks to @Krinkle for all the help and support here as well.

Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL · Credits