Since the release to MediaWiki.org on Wednesday, posting a message is crazy slow. We clocked it at 11 seconds between hitting "Reply" and having the message show up on the page.
We need to cherrypick a fix so that this doesn't follow the train next week.
Tested this on Firefox & Chrome.
| Status | Subtype | Assigned | Task | ||
|---|---|---|---|---|---|
| Resolved | matthiasmullie | T98408 Posting a Flow message on MediaWiki.org is really, really slow | |||
| Resolved | • Mattflaschen-WMF | T98534 Pass metadataonly true to API requests |
It shouldn't be this slow. It may be partly due to the recent split between the POST API and the follow-up view. But that's probably not the only factor. We have to figure out if all of this is due to Flow changes.
I've tested a couple of calls & the POST requests take roughly 3x as long (2-4s) as the GET requests (700ms-1s) to get the data we need to render, so it doesn't look like the recent split has made this much worse (but probably slightly, because of the additional network request).
We should be able to cut down on the time the POST needs once we stop outputting all render data (for BC reasons) with https://gerrit.wikimedia.org/r/#/c/203826/. Though that likely won't affect too much.
I've done some profiling on my machine and couldn't find much interesting. Over half of the processing time is spent on curl (reaching out to parsoid) & mysql.
I started looking into Parsoid. Looks like https://gerrit.wikimedia.org/r/#/c/205503/ drastically slowed down parsing our stuff.
I have yet to figure out what that patch was about and if that patch caused (problem on Parsoid's end) or surfaced (problem on our end) the problem.
First parse of a topic, before this patch:
[info][localhost/Topic:Sguw28nr2kuzhxg3] started parsing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed parsing in 1480 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 849 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 961 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 1065 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 1078 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 1100 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 1091 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 1122 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 1161 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 1289 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 1031 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 28 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 23 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 27 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 20 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 22 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 22 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 17 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 30 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 19 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 25 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 21 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 15 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 17 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 10 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 17 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 9 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 9 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 9 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 12 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 9 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 11 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 10 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 9 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 11 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 7 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 7 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 8 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 8 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 7 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 8 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 13 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 8 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 8 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 13 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 18 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed serializing in 14 ms
After this patch:
[info][localhost/Topic:Sguw28nr2kuzhxg3] started parsing [info][localhost/Topic:Sguw28nr2kuzhxg3] completed parsing in 1626 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 2817 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 3123 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 2543 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 2911 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 2104 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 2035 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 2058 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 2014 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 1982 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 2006 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 458 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 414 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 408 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 407 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 419 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 411 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 429 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 401 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 378 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 360 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 347 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 326 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 309 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 297 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 287 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 285 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 276 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 302 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 291 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 270 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 271 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 270 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 277 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 296 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 290 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 376 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 331 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 341 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 337 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 353 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 358 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 356 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 348 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 356 ms [info][localhost/Topic:Sguw28nr2kuzhxg3] started serializing [info][localhost/Topic:Sguw28nr2kuzhxg3?oldid=2471] completed serializing in 372 ms
Change 210009 had a related patch set uploaded (by Matthias Mullie):
Don't parse html->wikitext if we don't have to
The problem was on our (Flow) end: we have deprecated-but-not-yet-removed write API output, and so it still tries to output the content according to 'format' param (which, when submitting replies in wikitext editor, is wikitext)
So we would ask Parsoid to convert HTML back to wikitext for every post in that topic, even though we don't need that at all. Above patch will fix that.
As for Parsoid: even though this particular problem was a Flow-specific issue, that "serializing" time is still drastically slower prior & after https://gerrit.wikimedia.org/r/#/c/205503/
I have no idea how all of that works and it may very well be for valid reasons (maybe old was relying on caches that it shouldn't? IDK)
Just in case you still want to look into this, here's how to reproduce what I was seeing. I'm assuming you have a working Flow setup, and above patch has not been applied (if you need help setting up Flow, let me know)
# create a topic (&page= should point to a Flow-enabled page; in my case Talk:Test) curl --data "action=flow&submodule=new-topic&nttopic=topictitle&ntcontent=firstpostcontent&ntformat=wikitext&ntmetadataonly=1&page=Talk:Test&token=%2B%5C&format=json" http://mediawiki.dev/api.php
somewhere in that response is
grab that info
# submit a reply curl --data "action=flow&format=json&submodule=reply&page=Some-page-here&repreplyTo=some-id-here&repcontent=replycontent&repformat=wikitext&token=%2B%5C&format=json" http://mediawiki.dev/api.php # e.g. curl --data "action=flow&format=json&submodule=reply&page=Topic:Sh3nnzgb4axfrgcz&repreplyTo=sh3nnzgb4axfrgcz&repcontent=replycontent&repformat=wikitext&token=%2B%5C&format=json" http://mediawiki.dev/api.php
Every new topic will result in all previous topics being parsed from HTML (storage format) back to wikitext (that was Flow's fault). Prior to that patch, it seems that happened a lot quicker that after that patch.
Comparison(posting a simple paragraph) - some typical numbers
https://www.mediawiki.org/wiki/Talk:Sandbox
http://en.wikipedia.beta.wmflabs.org/w/index.php?title=To
| Time betalabs | Time mw | ||
| api.php | POST | 1.17 s | 4.18 s |
| event?%7B%22event%22%3A%7B%22entrypoint%22%3A%22reply-post... | POST | 351 ms | 31 ms |
| api.php?action=flow&format=json&.. | GET | 169ms | 21ms |
| event?%7B%22event%22%3A%7B%22entrypoint%22%3A%22reply-post... | POST | 820 ms | 813 ms |
https://gerrit.wikimedia.org/r/#/q/I97e194e2e1ed0ec5a115a847119fd3d8e7e6bbde,n,z should have improved this in production (it's already been fully deployed).
I think the POSTs to event are the Beacon requests for EventLogging. They should not visibly delay the user in any way. The first api.php request listed is probably the actual POST, and the second api.php is the follow-up GET to re-render.
On the Parsoid side, the discussion here https://gerrit.wikimedia.org/r/#/c/205503/3/lib/mediawiki.DOMUtils.js (L2547) should provide some context. The difference being that after that change we're fetching the page source (and possibly parsing it to attempt selser). We need to close T96923 before non-selective serialization doesn't require the source (though things seemed to have been working for you just fine before that patch).
We've definitely regressed in your use case but I'd need to dig in a bit to see what payload / endpoint flow uses to better understand the requirements.
There is only one scenario right now, where lack of access to original source can introduce dirty diff, and that seems to be localized category magicword string on non-english wikis. So, there is no real semantic failure that will be caused by that scenario. For Flow where the wikitext originates from HTML, it should be safe to not fetch src at all.
Change 210843 had a related patch set uploaded (by Arlolra):
Restore speedy non-selser serialization