Page MenuHomePhabricator

Mediawiki namespace pages, including CentralNotice banners, are slow to save
Closed, ResolvedPublic

Description

Hi Andy, tagging you here. For about the last week, several of us on the banner team, including @Pcoombe, @jrobell & @TSkaff, have noticed much longer save times on banners - sometimes 15 or even 30 seconds, when it used to be more like 5. This happens when creating a new banner or saving edits to an existing banner.

Timing seems coincidental with the solution to T144952, but might not be related. Thanks!

Event Timeline

There are a very large number of changes, so older changes are hidden. Show Older Changes
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptFeb 14 2017, 6:11 PM
DStrine removed AndyRussG as the assignee of this task.Feb 14 2017, 10:09 PM
DStrine added a subscriber: AndyRussG.
ggellerman triaged this task as Normal priority.Feb 14 2017, 10:09 PM

Hi! Aaaarg, this is pretty awful. I tried saving two different banners. The first one took 2 minutes, and the second took 40 seconds. Possibly relevant: the first one contained i18n messages.

Do we happen to have more precise info on when this started (asking just in case we do...)? Thanks!!!

I first noticed this at least as early as February 3rd and it would have been maybe a day or so that I noticed it start happening.

Thanks @Jseddon!

Some notes so far:

  • This is not happening on the beta cluster.
  • On production, it only happens when you change banner content. If you change another banner setting without modifying content, it's pretty quick.
  • The change to i18n message caching (which likely solved the other bug) did go out to Meta with wmf.10 on Feb 1.

All of the above is coherent with the possibility that the changes that fixed that bug caused this....

I noticed that the actual edit to the banner shows up in "my contributions" almost immediately, although the CN interface still makes it appear like the save is taking a long time.

I noticed that the actual edit to the banner shows up in "my contributions" almost immediately, although the CN interface still makes it appear like the save is taking a long time.

Brilliant find!! Makes it pretty clear the delay is in updating the i18n messages. (Again, this is coherent with the theory that it's from the fix to missing banner messages.)

Hmm, this makes it pretty clear:

  • Edit a banner as wiki page.
  • It's very slow to save, just like in the CN admin interface.
  • You can open the banner's wiki page in another tab and see the results of your changes long before the edit page finishes loading.

This seems to affect editing of other pages in the Mediawiki: namespace, too. Same thing happened when I edited MediaWiki:Spam-blacklist-- it took 17 seconds, but I was able to to see the updated version in another tab almost immediately.

AndyRussG renamed this task from Central Notice banners slow to save to Mediawiki namespace pages, including CentralNotice banners, are slow to save.Feb 23 2017, 8:42 PM
AndyRussG added a project: MediaWiki-Cache.
AndyRussG added a subscriber: aaron.

I also tried editing a short message in the Mediawiki: namespace (since the MessageCache treats messages longer than 1024 bytes differently). It was still very slow (16 seconds).

One more test really confirms this: I edited a test banner, and, while waiting for the CN admin interface to finish loading, viewed it both as a Mediawiki namespace page and as a banner using banner preview system. The wiki page showed the change right away, but the previewed banner (which uses BannerLoader and i18n messages) didn't show the change until after the CN admin interface came back.

Change 340551 had a related patch set uploaded (by AndyRussG):
[mediawiki/core] [WIP] In MessageCache, update shared caches in POSTSEND

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

awight assigned this task to AndyRussG.Mar 1 2017, 7:23 PM

@aaron Hi! Are you able to give some feedback on the core patch? I think it works from the perspective of CentralNotice, but I imagine there there could be implications that we're not aware of for other code that relies on i18n messages. Thanks much in advance!! :)

aaron added a comment.Mar 9 2017, 3:05 AM

17 seconds is the number I got a few years ago when timing how long it takes to rebuild the message cache. It goes down to 1-2 seconds on a warm-cache run (at least it used to), presumably the external store blob fetches are the big determinant. If they are all uncached it will be be slow, if they all are...then much faster. Perhaps the edit stashing system could warm the text caches when MW: pages are being edited...

Change 341968 had a related patch set uploaded (by Aaron Schulz):
[mediawiki/core] Make MessageCache use the immutable text cache during cache rebuilds

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

Change 341968 merged by jenkins-bot:
[mediawiki/core] Make MessageCache use the immutable text cache during cache rebuilds

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

Change 344105 had a related patch set uploaded (by Hashar):
[mediawiki/core] Revert "Make MessageCache use the immutable text cache during cache rebuilds"

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

Change 344106 had a related patch set uploaded (by Hashar):
[mediawiki/core] Revert "Make Revision::getRevisionText() cache the converted text"

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

Change 344106 abandoned by Hashar:
Revert "Make Revision::getRevisionText() cache the converted text"

Reason:
Lets fix it yeah :-}

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

hashar added a subscriber: hashar.Mar 22 2017, 1:06 PM

Typo fixed ExternalStore::decompressRevisionText -> self::decompressRevisionText https://gerrit.wikimedia.org/r/#/c/344109/

Change 344105 abandoned by Krinkle:
Revert "Make MessageCache use the immutable text cache during cache rebuilds"

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

aaron added a comment.Mar 30 2017, 1:58 AM

Is this still a problem?

hashar removed a subscriber: hashar.Mar 30 2017, 12:04 PM

Still slow for me. @spatton ?

Still slow for me too, though today I'm seeing save times of more like 10 seconds vs. the original upper limit of 30 that prompted this task. That's for a variety of actions: creating a new banner, cloning from an existing banner, as well as saving revisions to existing banners.

Krinkle moved this task from Backlog to MessageCache on the MediaWiki-Cache board.Apr 7 2017, 10:47 PM
AndyRussG added a comment.EditedMay 11 2017, 6:57 PM

I just updated a test campaign for different bug, and saving was quite speedy! Can anyone confirm the issue is still occurring, or, if you're not sure, mention about how long campaigns are taking to save, on average? Thanks!!! :)

(See correction below)

aaron added a comment.May 11 2017, 7:16 PM

Could be related to T164666.

I just updated a test campaign for different bug, and saving was quite speedy! Can anyone confirm the issue is still occurring, or, if you're not sure, mention about how long campaigns are taking to save, on average? Thanks!!! :)

Mmm my previous comment is completely silly and wrong, BTW... This issue here is slow-saving banners, not campaigns!! Apologies! (/me secretly blames lack of coffee...)

It would still be good to hear any updates on the status of this, though! Thanks!!!!!!

Saving and cloning banners does seem faster to me now. @spatton ?

@AndyRussG and @Pcoombe, looks like the same save times that I was seeing previously. Just to make it easier to track and compare later, here are some counts I got:

18.9 seconds to clone a banner that was created on 5/12
12.8 seconds to clone our current best banner template, created in early April

^ not implying that it's faster to clone 'old' vs 'new' banners.

12.3 seconds to add new banner
13.7 seconds to add another new banner

Hi! I tested saving some banners again, and got mostly similar results. Saved two different banners a few times, from both the CentralNotice interface and as MediaWiki namespace pages. All except two times, it took 12-15 seconds. Two outliers: once it took 4 seconds, and one time it took 60 seconds. When it took 60 seconds, it was the first time I'd saved that banner.

In general, I guess 12 seconds to save a banner on most occasions probably isn't desirable performance, though definitely better than before... 8p

MusikAnimal added a subscriber: MusikAnimal.EditedApr 2 2018, 9:19 PM

Hello, this issue has been happening to me since late 2017. It definitely didn't start a year ago when this task was created. Any edit I make to the MediaWiki namespace (not just banners), no matter how small, takes 5+ seconds to save, sometimes much longer. I have witnessed this on enwiki, mediawiki, metawiki, and testwiki. I have not observed this on other non-WMF MediaWiki installations. Hope this helps

TheDJ added a subscriber: TheDJ.Apr 3 2018, 10:09 AM

@MusikAnimal I've been noticing slow saves on Common.js and Common.css as well.

Reporting that I'm also seeing noticeably slower save times when editing banners in CN, even if I'm just changing Display to or Display on settings. Changes to those toggles have typically saved within a couple seconds, and I'm now seeing upwards of 20 seconds to save.

Reporting that I'm also seeing noticeably slower save times when editing banners in CN, even if I'm just changing Display to or Display on settings. Changes to those toggles have typically saved within a couple seconds, and I'm now seeing upwards of 20 seconds to save.

Thanks @spatton! I expect slowness in changing banner settings like that is a different issue, assuming changes are not made simultaneously in banner content, since there's a pretty elaborate, different code path for banner content changes. If you can confirm that it happens like that, could you perhaps make a different ticket?

Also, what sort of times are you seeing for changes in banner content when there are no translatable messages involved? Is it the same if you edit the banner content directly via the Mediawiki namespace page?

Thanks again!! :)

This may well be a less severe symptom as the same problem that's causing T203925: Save times for changes to translation variable text in centralnotice paralysingly slow. (More details here: T203925#4609441.)

Analysis at https://phabricator.wikimedia.org/T203925#4616856 suggests that the issue is that every single content revision is being pulled individually from the cache. Even when memcache returns quickly (500us), in some instances we're making tens of thousands of independent calls to memcache and they're adding up. It looks like maybe some sort of batching in MessageCache::getFromDB is called for, but I haven't really deep-dived.

Change 340551 abandoned by AndyRussG:
[WIP] In MessageCache, update shared caches in POSTSEND

Reason:

I'd recommend closing this patch given the alternatives

Agreed! :)

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

Krinkle moved this task from Perf issue to Watching on the Performance-Team (Radar) board.
DStrine closed this task as Resolved.May 13 2019, 8:01 PM