1.41.0-wmf.7 increases Memcached call rate by +100%
Closed, ResolvedPublicPRODUCTION ERROR
Actions

Assigned To

Authored By

	Krinkle
	May 5 2023, 2:05 AM

Description

https://grafana.wikimedia.org/d/2Zx07tGZz/wanobjectcache?orgId=1&from=now-8d&to=now

Memcached cache miss rate increases by > 100%:

SqlBlobStore_blob
page_content_model
revision_row_1_29

Memcached cache hit rate increases:

SqlBlobStore_blob + 50%
page_content_model + > 100%

Those are huge numbers to hold and sustain throughout (not a short burst). This warrants investigation as that seems likely result of something having broken how pages are cached, or resujlt of accidentally adding calls in a critical path somewhere.

I'm guessing for now that the rise resembles this week's first group1+group2 deploys, and then the revert for T336008 to "just" group1.

Details

Related Changes in Gerrit:

	Subject	Repo	Branch	Lines +/-
	Revert "api: Use RevisionStore::newRevisionsFromBatch to fetch revision records"	mediawiki/core	wmf/1.41.0-wmf.7	+4 -56

Customize query in gerrit

Related Objects

Mentioned In: T336008: MWException: Internal error in ApiQueryRevisionsBase::getRevisionRecords: RevisionStore does not return record for [n]
T330213: 1.41.0-wmf.7 deployment blockers
Mentioned Here: T330213: 1.41.0-wmf.7 deployment blockers
T336008: MWException: Internal error in ApiQueryRevisionsBase::getRevisionRecords: RevisionStore does not return record for [n]

Event Timeline

Krinkle created this task.May 5 2023, 2:05 AM

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptMay 5 2023, 2:05 AM

Krinkle updated the task description. (Show Details)May 5 2023, 2:06 AM

Krinkle updated the task description. (Show Details)May 5 2023, 2:13 AM

revision_row_1_29 is generated by RevisionStore::getRevisionRowCacheKey and that is called by RevisionStore::getKnownCurrentRevision
SqlBlobStore_blob is generated by SqlBlobStore::getCacheKey, called by SqlBlobStore::getBlob and SqlBlobStore::expandBlob
page_content_model is used in WikiPage::getContentModel

Does not found something directly related to that

ArielGlenn subscribed.May 5 2023, 6:59 AM

Maybe https://gerrit.wikimedia.org/r/c/mediawiki/core/+/910808?

@Krinkle, am I wrong in thinking this ought to block wmf.7? (Edit: Sorry, I see it's already a child task.)

Raising to UBN! as blocker.

In T336022#8828968, @Ladsgroup wrote:

Maybe https://gerrit.wikimedia.org/r/c/mediawiki/core/+/910808?

This one was mentioned in our other blocker (T336008: MWException: Internal error in ApiQueryRevisionsBase::getRevisionRecords: RevisionStore does not return record for [n]), too.

@Umherirrender or @Jdforrester-WMF what are your thoughts on the possibility of a revert/try-again-next week for that one? Is that even possible?

For me the api module is not using RevisionStore::getKnownCurrentRevision or WikiPage::getContentModel

There is also a change directly to the caches - https://gerrit.wikimedia.org/r/c/mediawiki/core/+/830706 - but that seems to be tested in producation already.

It should be possible to revert the api change.

Change 915719 had a related patch set uploaded (by Umherirrender; author: Umherirrender):

[mediawiki/core@wmf/1.41.0-wmf.7] Revert "api: Use RevisionStore::newRevisionsFromBatch to fetch revision records"

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

gerritbot added a project: Patch-For-Review.May 5 2023, 5:24 PM

Mentioned in SAL (#wikimedia-operations) [2023-05-05T18:25:20Z] <brennen> train 1.41.0-wmf.7 (T330213): trying revert for T336008, T336022

Stashbot mentioned this in T336008: MWException: Internal error in ApiQueryRevisionsBase::getRevisionRecords: RevisionStore does not return record for [n].May 5 2023, 6:25 PM

Change 915719 merged by jenkins-bot:

[mediawiki/core@wmf/1.41.0-wmf.7] Revert "api: Use RevisionStore::newRevisionsFromBatch to fetch revision records"

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

Mentioned in SAL (#wikimedia-operations) [2023-05-05T18:42:44Z] <brennen@deploy1002> Started scap: Backport for [[gerrit:915719|Revert "api: Use RevisionStore::newRevisionsFromBatch to fetch revision records" (T336008 T336022)]]

Mentioned in SAL (#wikimedia-operations) [2023-05-05T18:44:17Z] <brennen@deploy1002> umherirrender and brennen: Backport for [[gerrit:915719|Revert "api: Use RevisionStore::newRevisionsFromBatch to fetch revision records" (T336008 T336022)]] synced to the testservers: mwdebug1001.eqiad.wmnet, mwdebug1002.eqiad.wmnet, mwdebug2002.codfw.wmnet, mwdebug2001.codfw.wmnet

Mentioned in SAL (#wikimedia-operations) [2023-05-05T18:57:05Z] <brennen@deploy1002> Finished scap: Backport for [[gerrit:915719|Revert "api: Use RevisionStore::newRevisionsFromBatch to fetch revision records" (T336008 T336022)]] (duration: 14m 21s)

Narrowed it down a bit.
Here is a flamegraph of when wmf.6 was the majority and when wmf.7 was the majority:

Went with wall for obvious reasons.

API quota goes from 34% to 40% which basically all of it is because of increase in ApiParse. They also have a drastically different flamegraph now:

wmf.6:

wmf.7:

Now need to figure out what made the shift but that looks like a change in parsing.

Maintenance_bot removed a project: Patch-For-Review.May 5 2023, 7:10 PM

Can't say for sure but https://gerrit.wikimedia.org/r/c/mediawiki/core/+/901690 might have had some unintended consequences.

Either parsing got really slower or ParserCache started to become fragmented due to TOC flags.

cc. @cscott @matmarex

We've got Revert "api: Use RevisionStore::newRevisionsFromBatch to fetch revision records" out to wmf.7; train is still at group1. It seems possible this has made a difference?

2023-05-05-13:16:42.png (804×744 px, 258 KB)

...but doesn't seem like root cause?

Looking at the webrequest sample graph, it doesn't seem to be a major spike in calls to action=parse: https://w.wiki/6fcE (remember to multiply numbers by 128). So calls to action=parse definitely get a lot slower in wmf.7

Ladsgroup added a project: Content-Transform-Team.May 5 2023, 7:25 PM

I can't debug much more anymore, it's quite late here. If anyone wants to take over, feel free. If not, I'll pick it up early Monday.

I can't debug much more anymore, it's quite late here. If anyone wants to take over, feel free. If not, I'll pick it up early Monday.

Thanks for the assist!

In T336022#8830451, @Ladsgroup wrote:

Can't say for sure but https://gerrit.wikimedia.org/r/c/mediawiki/core/+/901690 might have had some unintended consequences.

Either parsing got really slower or ParserCache started to become fragmented due to TOC flags.

I don't think that change can cause cache fragmentation. I don't mind it if you try to revert to see if that fixes the issue, but it seems unlikely to me.

There are rolling reboots of the Codfw memcached hosts this week as part of T335846.
https://sal.toolforge.org/production?p=0&q=%22sre.hosts.reboot%22&d=2023-05-04

These reboots naturally wipe the cache memory of each host as it reboots, one at a time.

This explains the sudden regression in cache misses (which accidentally coincided with the train).
This explains the very slow recovery over the past 48 hours (not correlated with train or revert), as the values are slowly being recomputed or backfilled in memcached.

This might also explain the regression in ApiParse latency that @Ladsgroup shows as that would naturally suffer when there is a decrease in overall cache effectiveness for various internal values used throughout the process of parsing a page, its templates, its thumbnails, etc.

But, this does not explain an increase in total WAN cache calls (it only explains a shift from hits to misses, not an added bulk of new hits or new misses). That still remains a mystery such as these huge increase for key groups such as page-content-model that remain are more than double even now, without any apparent decrease in cache hits.

https://grafana.wikimedia.org/d/lqE4lcGWz/wanobjectcache-key-group?var-kClass=page_content_model&orgId=1&from=now-7d&to=now

Screenshot 2023-05-05 at 23.14.57.png (1×1 px, 159 KB)

Screenshot 2023-05-05 at 23.14.56.png (796×1 px, 162 KB)

I suspect this may be a case of layered caching, where a higher layer is normally preventing this key from being reached at all, not even as a cache hit. However, we're talking hundreds of thousands per minute, no longer tens of millions, at a layer that can handle that (Memcached).

And in terms of ground truth, latency appears not impacted on either appservers nor api_appservers at https://grafana.wikimedia.org/d/RIA1lzDZk/application-servers-red.

I'll keep this task open to confirm the ApiParse recovery with @Ladsgroup, and to further understand the page-content-model cache behaviour as that's currently not well understood (at least not by me). No longer a train blocker.

Krinkle removed a parent task: T330213: 1.41.0-wmf.7 deployment blockers.May 5 2023, 10:24 PM

Ladsgroup added a comment.May 9 2023, 9:35 AM

This comment was removed by Ladsgroup.

That's explains it, thanks for the work. I think it's fine to close this given that reads mostly recovered.

Krinkle closed this task as Resolved.May 9 2023, 10:14 AM

ReleaseTaggerBot added a project: MW-1.41-notes (1.41.0-wmf.7; 2023-05-01).May 16 2023, 1:02 PM

	F36977211: Screenshot 2023-05-05 at 23.14.56.png
	May 5 2023, 10:24 PM

	F36977209: Screenshot 2023-05-05 at 23.14.57.png
	May 5 2023, 10:24 PM

	F36976194: Screenshot 2023-05-05 at 03.11.10.png
	May 5 2023, 2:13 AM

	F36976197: Screenshot 2023-05-05 at 03.12.02.png
	May 5 2023, 2:13 AM

	F36976192: Screenshot 2023-05-05 at 03.09.47.png
	May 5 2023, 2:13 AM

	F36977118: grafik.png
	May 5 2023, 7:06 PM

	F36977116: grafik.png
	May 5 2023, 7:06 PM

1.41.0-wmf.7 increases Memcached call rate by +100%Closed, ResolvedPublicPRODUCTION ERRORActions

Description

Details

Related Objects

Event Timeline

1.41.0-wmf.7 increases Memcached call rate by +100%
Closed, ResolvedPublicPRODUCTION ERROR
Actions