[go: nahoru, domu]

Page MenuHomePhabricator

StructuredDiscussions hook onContributionsLineEnding a tad slow on Special:Contributions
Open, LowPublic

Description

Information about the wiki (https://allthetropes.org, hosted by wiki farm Miraheze):
MediaWiki: 1.34.2
PHP: 7.3.19-1~deb10u1 (fpm-fcgi)
MariaDB: 10.4.13-MariaDB-1:10.4.13+maria~buster-log
StructuredDiscussions: 5a1c2eb72f15a29dcc96ad5f3a5a59e88bd1aa00 (branch REL1_34)

When I would like to view my own contributions (Special:Contributions/Southparkfan), I noticed via tideways profiling about 50% of the parse time is spent in the MediaWiki hooks. Since there is no overview available of cumulative time spent per hook event, I decided to hack something on my own. My conclusion was that the StructuredDiscussions hook onContributionsLineEnding has a major effect on Special:Contributions, see profile P12202. Multiple refreshes give me 19-23% for onContributionsLineEnding.

Since Wikimedia uses StructuredDiscussions as well, I decided to get some profiles Wikimedia as well. Thanks to @dpifke, we have an XHGui profile of https://mediawiki.org/wiki/Special:Contributions/Southparkfan: https://performance.wikimedia.org/xhgui/run/view?id=5f2de5c63f3dfad15b2fb491. A few statistics (including HookContainer::run, to see how much time inside all hook runs is spent by the Flow hook) for various wikis:

  1. https://mediawiki.org/wiki/Special:Contributions/Southparkfan (Flow enabled)
    1. Request 1
      1. 1071.020 1 - wfIndexMain
      2. 488.974 2486 - MediaWiki\HookContainer\HookContainer::run
      3. 232.728 50 - MediaWiki\HookContainer\HookRunner::onContributionsLineEnding
    2. Request 2
      1. 1059.365 1 - wfIndexMain
      2. 491.729 2486 - MediaWiki\HookContainer\HookContainer::run
      3. 236.658 50 - MediaWiki\HookContainer\HookRunner::onContributionsLineEnding
    3. Request 3
      1. 1224.778 1 - wfIndexMain
      2. 532.531 2486 - MediaWiki\HookContainer\HookContainer::run
      3. 247.485 50 - MediaWiki\HookContainer\HookRunner::onContributionsLineEnding
  2. https://en.wikipedia.org/wiki/Special:Contributions/Southparkfan (Flow enabled)
    1. Request 1
      1. 888.130 1 - wfIndexMain
      2. 192.427 2872 - MediaWiki\HookContainer\HookContainer::run
    2. Request 2
      1. 723.839 1 - wfIndexMain
      2. 165.677 2871 - MediaWiki\HookContainer\HookContainer::run
    3. Request 3
      1. 802.282 1 - wfIndexMain
      2. 193.255 2871 - MediaWiki\HookContainer\HookContainer::run

Conclusions:

  • On mediawikiwiki, about 43%-46% of the time is spent running hooks, compared to 21%-24% on enwiki.
  • About 46%-48% of the execution time while running hooks is consumed by the StructuredDiscussions onContributionsLineEnding hook.
  • If you subtract the wall time of MediaWiki\HookContainer\HookRunner::onContributionsLineEnding from mediawikiwiki's wfIndexMain, the total execution time is very similar to enwiki's.
  • All above points are also found on Miraheze wikis, reducing the likelihood of a Wikimedia-only issue.

Event Timeline

Restricted Application added subscribers: RhinosF1, Reception123, Aklapper. · View Herald Transcript

This hook isn't expected to be a cheap hook to augment the display, for edits that are Flow contributions, this hook is where the edit information itself is queried from the database.

How much it does, depends on whether there are Flow edits in the results. If Flow queries themselves are slow for some reason, that could have its own ticket for the Growth team to look into but the hook isn't the problem here.

I've untagged Perf team since this is a fairly well-understood dynamic and there isn't a clear question for us here. The instrumentation tools are working as expected, and the general infrastructure is also available in core to make these efficient if needed/possible.

Assigning to self to re-evaluate after T285917 and https://gerrit.wikimedia.org/r/c/mediawiki/core/+/714693 are resolved and deployed.

Krinkle renamed this task from StructuredDiscussions hook onDeletedContributionsLineEnding a tad slow on Special:Contributions to StructuredDiscussions hook onContributionsLineEnding a tad slow on Special:Contributions.Jan 4 2022, 8:16 PM
Krinkle updated the task description. (Show Details)

As of writing, the stats are more or less the same as in Aug 2020.

For https://www.mediawiki.org/wiki/Special:Contributions/Southparkfan (Private browsing, logged-out, GET request, mwdebug1001, after 1 warmup on the same mwdebug backend without XHGui, 1 run with XHGui).

XHGui profile

1,100 ms overall,
of which 466ms in HookContainer::run,
and 225ms (50 calls) spent in onContributionsLineEnding.

Flow\Hooks::onContributionsLineEnding is mainly Flow\Formatter\ContributionsFormatter::format, which spends most of its time in these methods: (XHGui symbol page):

  • RevisionFormatter::formatApi (permission checks)
  • AbstractFormatter::formatDescription (message parsing)
  • ChangesList::showCharacterDifference (message parsing)
  • AbstractFormatter::getTitleLink (LinkRenderer)
Krinkle moved this task from Limbo to Perf recommendation on the Performance-Team (Radar) board.
Krinkle subscribed.

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

[mediawiki/extensions/Flow@master] ContributionsFormatter: Pass missing context to showCharacterDifference()

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

Change 751493 merged by jenkins-bot:

[mediawiki/extensions/Flow@master] ContributionsFormatter: Pass missing context to showCharacterDifference()

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