Page MenuHomePhabricator
Create Task
Maniphest T116971

Special:Watchlist takes 23 seconds to start loading on mediawiki.org
Open, Needs TriagePublic
Actions

Description

Since several days (perhaps a few weeks), https://www.mediawiki.org/wiki/Special:Watchlist takes many seconds to load (23 seconds time to first byte right now), every single time I attempt to open it.

As I removed all "Thread" pages from watchlist before the LQT conversion, I only have 3300 pages in watchlist. I use 0 days, 1000 changes, extended watchlist and enhanced watchlist in https://www.mediawiki.org/wiki/Special:Preferences#mw-prefsection-watchlist , which is arguably the heaviest configuration possible, but hardly extraordinary with so few pages.

On all other wikis, things are still fine, hence I suspect this has to do with Flow. Can someone provide a script or trick to remove all pages with a Flow talk page from my watchlist, to verify?

Related Objects

Event Timeline

Nemo_bis created this task.Oct 28 2015, 9:00 PM
Nemo_bis raised the priority of this task from to Needs Triage.
Nemo_bis updated the task description. (Show Details)
Nemo_bis added projects: MediaWiki-Watchlist, Performance Issue, StructuredDiscussions.
Nemo_bis subscribed.
Restricted Application added a project: Collaboration-Team-Triage. · View Herald TranscriptOct 28 2015, 9:00 PM
Restricted Application added a subscriber: Aklapper. · View Herald Transcript
aaron subscribed.Oct 28 2015, 9:02 PM

Maybe you can see the slowest methods via https://wikitech.wikimedia.org/wiki/Debugging_in_production#Showing_profiling_data_for_MediaWiki_requests and "view source".

Nemo_bis added a comment.Oct 28 2015, 9:22 PM

Ok. It took 43 seconds this way! What should I be looking for? I don't see anything in the HTML, perhaps I got a truncated response. I'll email you the HAR.

aaron added a comment.Oct 28 2015, 9:38 PM

Just viewing a the watchlist with ?foceprofile and the extension enabled (clicking the globe) is enough. You will see the profile table as an HTML comment at the bottom of the page. That can be posted here.

Nemo_bis added a comment.EditedOct 28 2015, 10:11 PM
In T116971#1763613, @aaron wrote:

Just viewing a the watchlist with ?foceprofile and the extension enabled (clicking the globe) is enough. You will see the profile table as an HTML comment at the bottom of the page. That can be posted here.

I also tried the extension in Firefox and I see no such thing on any page...

OK, got it in Chromium:

<!--
100.00% 31566.225      1 - main()
 99.97% 31555.179      1 - MediaWiki::run
 99.96% 31554.959      1 - MediaWiki::main
 99.45% 31392.829      1 - MediaWiki::performRequest
 99.40% 31376.418      1 - SpecialPageFactory::executePath
 99.40% 31376.072      1 - SpecialPage::run
 99.39% 31374.129      1 - SpecialWatchlist::execute
 99.38% 31369.551      1 - ChangesListSpecialPage::execute
 98.62% 31129.809      1 - ChangesListSpecialPage::webOutput
 98.48% 31087.489      1 - SpecialWatchlist::outputChangesList
 88.49% 27932.831   1000 - EnhancedChangesList::recentChangesLine
 83.29% 26292.331  86840 - Hooks::run
 80.97% 25559.993     13 - EnhancedChangesList::recentChangesBlock
 67.42% 21282.187    163 - EnhancedChangesList::recentChangesBlockGroup
 64.31% 20300.764    444 - Flow\Formatter\RevisionFormatter::formatApi
 54.77% 17289.199    803 - EnhancedChangesList::getLineData
 49.21% 15532.802   1000 - FlowHooks::onEnhancedChangesListModifyBlockLineData
 48.93% 15445.990    336 - Flow\Formatter\ChangesListFormatter::getTimestampLink
 45.11% 14237.978    803 - FlowHooks::onEnhancedChangesListModifyLineData
 44.46% 14034.327   6620 - Flow\RevisionActionPermissions::isAllowed
 41.97% 13247.958    444 - Flow\Formatter\RevisionFormatter::buildActions
 26.98% 8516.110  13252 - Flow\Data\BufferedCache::getMulti
 26.89% 8489.037  13252 - Flow\Data\BagOStuff\LocalBufferedBagOStuff::getMulti
 26.73% 8438.277  13252 - Flow\Data\BagOStuff\BufferedBagOStuff::getMulti
 26.54% 8377.696   5764 - Flow\Collection\AbstractCollection::getBoardWorkflow
 25.51% 8051.178   5700 - Flow\Collection\PostCollection::getBoardWorkflowId
 24.23% 7648.597  14410 - MemcachedPeclBagOStuff::getMulti
 22.84% 7210.045  17183 - Message::toString
 22.84% 7209.618   8859 - DatabaseBase::select
 21.30% 6722.047   6483 - Flow\Data\ObjectLocator::findMulti
 21.13% 6670.683   8860 - DatabaseBase::query
 19.44% 6137.472   6482 - Flow\Data\Index\FeatureIndex::findMulti
 18.68% 5895.976   8653 - section.DatabaseBase::query
 18.11% 5716.741   6441 - Flow\Data\ObjectLocator::find
 16.62% 5246.886   8875 - DatabaseMysqli::doQuery
 16.34% 5158.826   6180 - Message::text
 13.52% 4268.597    197 - EnhancedChangesList::recentChangesBlockLine
 12.70% 4007.578    347 - ChangesList::insertArticleLink
 12.63% 3986.795   1000 - RCCacheEntryFactory::newFromRecentChange
 12.39% 3910.978    347 - FlowHooks::onChangesListInsertArticleLink
 12.39% 3910.240    347 - FlowHooks::processRecentChangesLine
 12.32% 3888.301     74 - Flow\Formatter\ChangesListFormatter::format
 12.24% 3865.019   6026 - Flow\Repository\TreeRepository::findRootPath
 12.15% 3834.089   6027 - Flow\Repository\TreeRepository::findRootPaths
 12.03% 3798.304    408 - Flow\UrlGenerator::thankAction
 12.02% 3794.141   8836 - Linker::link
 11.86% 3744.998   5700 - Flow\Collection\PostCollection::getWorkflowId
 11.84% 3736.654   2172 - Flow\Formatter\RevisionFormatter::processParam
 11.69% 3690.316   5700 - Flow\Repository\TreeRepository::findRoot
 11.30% 3567.413  15763 - Message::transformText
 11.20% 3534.989   4131 - DatabaseBase::selectRow
 11.15% 3518.081  15784 - MessageCache::transform
 10.95% 3457.651   2052 - Parser::transformMsg
 10.94% 3454.313   2052 - Parser::preprocess
 10.92% 3446.397   5764 - Flow\RevisionActionPermissions::isBoardAllowed
  8.61% 2719.406   3028 - Flow\Model\Workflow::isDeleted
  8.57% 2706.704   3028 - Title::newFromID
  8.10% 2556.593    444 - Flow\Formatter\RevisionFormatter::buildProperties
  7.28% 2297.494   2940 - DatabaseBase::selectField
  6.92% 2185.099   5461 - Title::isKnown
  6.87% 2169.722   1158 - ChangesList::formatCharacterDifference
  6.86% 2164.024   1134 - ChangesList::showCharacterDifference
  6.82% 2153.031  18257 - User::load
  6.73% 2125.125   1161 - Linker::userLink
  6.53% 2060.635   1000 - RCCacheEntryFactory::getUserLink
  6.53% 2060.000   5780 - Title::isAlwaysKnown
  6.13% 1935.826   5780 - GlobalUserPageHooks::onTitleIsAlwaysKnown
  6.10% 1925.514   5781 - GlobalUserPage::shouldDisplayGlobalPage
  6.10% 1925.445   2313 - PageTranslationHooks::renderTagPage
  6.09% 1922.317    189 - ChangesList::getArticleLink
  6.07% 1917.034   2316 - TranslatablePage::isTranslationPage
  6.06% 1913.981   2317 - Parser::replaceVariables
  6.02% 1899.065   2316 - MessageHandle::getKey
  6.01% 1898.375   4632 - MessageHandle::figureMessage
  5.97% 1884.517   3028 - section.query: SELECT page_namespace,page_title,page_id,page_len,page_is_redirect,page_latest,page_content_model FROM `page` WHERE page_id = 'X' LIMIT N  [TRX#8b4dfa715d53]
  5.95% 1877.540      1 - EnhancedChangesList::endRecentChangesList
  5.94% 1875.483   2316 - MessageIndex::getGroupIds
  5.92% 1867.563    744 - User::loadFromId
  5.85% 1845.535  30190 - Flow\FlowActions::getValue
  5.84% 1844.978   2316 - DatabaseMessageIndex::get
  5.14% 1623.359    741 - Flow\Collection\LocalCacheAbstractCollection::getLastRevision
  5.13% 1619.703  21786 - Hooks::run@1
  5.10% 1608.978   1161 - Linker::userToolLinks
  4.82% 1522.889    163 - EnhancedChangesList::getLogText
  4.82% 1522.784    741 - Flow\Collection\LocalCacheAbstractCollection::getAllRevisions
  4.81% 1518.506    741 - Flow\Collection\AbstractCollection::getAllRevisions
  4.54% 1433.924    924 - Flow\Templating::getContent
  4.54% 1432.807  34378 - Message::replaceParameters
  4.41% 1391.251    163 - FlowHooks::onGetLogText
  4.39% 1386.224     34 - Flow\Formatter\ChangesListFormatter::getLogTextLinks
  4.29% 1355.726   2316 - section.query: SELECT tmi_value FROM `translate_messageindex` WHERE tmi_key = 'X' LIMIT N  [TRX#8b4dfa715d53]
  4.23% 1336.471  12061 - User::getName
  4.14% 1307.470  15406 - BagOStuff::get
  4.01% 1266.990  15367 - Flow\Data\BagOStuff\LocalBufferedBagOStuff::doGet
  3.96% 1251.495   1633 - User::__toString
  3.90% 1231.252   2313 - PPFrame_Hash::expand
  3.90% 1230.861  15367 - Flow\Data\BagOStuff\BufferedBagOStuff::doGet
  3.60% 1135.712   2685 - Parser::braceSubstitution
  3.56% 1123.957      1 - ChangesList::initChangesListRows
  3.56% 1123.936      1 - FlowHooks::onChangesListInitRows
  3.56% 1123.113  58837 - Flow\Data\Utils\MultiDimArray::offsetGet
  3.56% 1122.704    743 - Flow\Data\Compactor\ShallowCompactor::expandCacheResult
  3.56% 1122.493      1 - Flow\Formatter\ChangesListQuery::loadMetadataBatch
  3.55% 1120.734   2062 - BagOStuff::get@1
  3.55% 1119.916   2074 - MemcachedBagOStuff::doGet
  3.54% 1116.492  17473 - Message::fetchMessage
  3.53% 1113.663   2075 - MemcachedPeclBagOStuff::getWithToken
  3.44% 1085.662    339 - Flow\Data\ManagerGroup::call
  3.44% 1085.538  11325 - Flow\RevisionActionPermissions::isRevisionAllowed
  3.43% 1082.654   1000 - ChangesList::getTags
  3.43% 1082.179    262 - Message::parse
  3.42% 1081.014   1000 - ChangesList::insertTags
  3.42% 1078.809    116 - ChangeTags::formatSummaryRow
  3.36% 1061.296    262 - Message::parseText
  3.35% 1058.587    262 - MessageCache::parse
  3.33% 1050.769  16741 - MessageCache::get
  3.25% 1027.055    448 - Title::getUserPermissionsErrorsInternal
  3.25% 1024.869    743 - Flow\Data\Index\FeatureIndex::findMulti@1
  3.23% 1018.219    447 - Title::userCan
  3.21% 1014.642    261 - Parser::parse
  3.21% 1012.785    446 - Title::quickUserCan
  3.18% 1003.196    444 - Flow\Templating::getUserLinks
  3.03% 957.735    444 - Title::checkPageRestrictions
  3.03% 956.884    444 - Title::getRestrictions
  3.03% 955.647    333 - Title::loadRestrictions
-->
aaron added a comment.Oct 28 2015, 10:14 PM

You can probably slip out the stuff < 3% to keep the comment smaller.

• Mattflaschen-WMF subscribed.EditedOct 30 2015, 11:16 PM

rEFLW529d6bd36cfb: Remove RC spam for moderated topics seems relevant at first glance. RC and watchlist share some code. However, it doesn't actually add any code loading roots or other data, AFAICT, just change what isRootAllowed returns.

So I don't really think that's responsible.

Quiddity subscribed.EditedOct 30 2015, 11:36 PM

Confirmation note: On mediawiki.org, with my preferences set to "0 days, 1000 changes", and for 2,228 pages. I also get a very long load time - roughly 30 seconds.
On enwiki, with those same settings, and my volunteer accounts 9,314 pages, and a few extra gadgets enabled, my watchlist takes ~7 seconds to load.

(Reproducing: Any staff who need to reproduce this, can copy my watchlist from https://office.wikimedia.org/wiki/User:Quiddity_%28WMF%29/Watchlists/MediaWiki into a test account's https://www.mediawiki.org/wiki/Special:EditWatchlist/raw )

@Nemo_bis a short-term fix for you, might be to change to "days=2" or a similarly low number. At least that fixes it for me.

Bawolff subscribed.Oct 31 2015, 12:14 AM

For reference, Quiddity's watchlist also shows a lot of time spent doing flow stuff

<!--
100.00% 52242.548      1 - main()
 99.91% 52193.319      1 - MediaWiki::run
 99.86% 52169.005      1 - MediaWiki::main
 99.53% 51995.123      1 - MediaWiki::performRequest
 99.46% 51961.140      1 - SpecialPageFactory::executePath
 99.46% 51960.925      1 - SpecialPage::run
 99.45% 51957.553      1 - SpecialWatchlist::execute
 99.33% 51894.786      1 - ChangesListSpecialPage::execute
 98.68% 51551.848      1 - ChangesListSpecialPage::webOutput
 98.31% 51358.326      1 - SpecialWatchlist::outputChangesList
 92.94% 48555.558   1184 - OldChangesList::recentChangesLine
 89.50% 46754.479  82154 - Hooks::run
 76.15% 39783.315   1184 - FlowHooks::onOldChangesListRecentChangesLine
 76.15% 39781.189   1184 - FlowHooks::processRecentChangesLine
 75.63% 39512.461    673 - Flow\Formatter\ChangesListFormatter::format
 61.75% 32260.721    673 - Flow\Formatter\RevisionFormatter::formatApi
 46.85% 24476.879  10798 - Flow\RevisionActionPermissions::isAllowed
 38.81% 20273.220    671 - Flow\Formatter\RevisionFormatter::buildActions
 31.84% 16632.052  25202 - Flow\Data\BufferedCache::getMulti
 31.75% 16585.798  25202 - Flow\Data\BagOStuff\LocalBufferedBagOStuff::getMulti
 31.56% 16485.839  25202 - Flow\Data\BagOStuff\BufferedBagOStuff::getMulti
 27.20% 14211.746  26592 - MemcachedPeclBagOStuff::getMulti
 25.92% 13541.764   9339 - Flow\Collection\AbstractCollection::getBoardWorkflow
 25.05% 13087.251   9277 - Flow\Collection\PostCollection::getBoardWorkflowId
 24.13% 12606.009  11742 - Flow\Data\ObjectLocator::findMulti
 22.04% 11514.607  11742 - Flow\Data\Index\FeatureIndex::findMulti
 21.00% 10969.560  28979 - Message::toString
 20.51% 10716.494  11693 - Flow\Data\ObjectLocator::find
 20.28% 10593.586  13690 - DatabaseBase::select
 18.82% 9832.198  13691 - DatabaseBase::query
 16.74% 8744.962  13384 - section.DatabaseBase::query
 16.25% 8487.524   1184 - OldChangesList::formatChangeLine
 15.66% 8182.465  11728 - Message::text
14.81% 7739.389  13708 - DatabaseMysqli::doQuery
 14.56% 7605.681  11038 - Flow\Repository\TreeRepository::findRootPaths
 14.54% 7595.990  11037 - Flow\Repository\TreeRepository::findRootPath
 14.04% 7332.785  10342 - Flow\Collection\PostCollection::getWorkflowId
 13.86% 7242.635  10347 - Flow\Repository\TreeRepository::findRoot
 11.41% 5963.259   3362 - Flow\Formatter\RevisionFormatter::processParam
 10.43% 5447.461  26418 - Message::transformText
 10.28% 5368.886  26418 - MessageCache::transform
 10.25% 5353.483    617 - Flow\UrlGenerator::thankAction
 10.09% 5271.722   3583 - Parser::transformMsg
 10.08% 5266.224   3583 - Parser::preprocess
  9.17% 4791.489   5857 - DatabaseBase::selectRow
  9.06% 4735.424    673 - Flow\Formatter\RevisionFormatter::buildProperties
  8.85% 4624.090   2414 - Flow\Collection\LocalCacheAbstractCollection::getLastRevision
  8.83% 4612.736   9339 - Flow\RevisionActionPermissions::isBoardAllowed
  8.48% 4429.106  10547 - Linker::link
  8.28% 4323.737   2416 - Flow\Collection\LocalCacheAbstractCollection::getAllRevisions
  8.26% 4312.889  70582 - Hooks::run@1
  8.25% 4310.402   2416 - Flow\Collection\AbstractCollection::getAllRevisions
  7.40% 3867.367   5276 - DatabaseBase::selectField
  7.32% 3822.309   1106 - ChangesList::insertUserRelatedLinks
  6.97% 3639.038   4249 - Flow\Model\Workflow::isDeleted
  6.93% 3622.298   4249 - Title::newFromID
  6.68% 3488.661  25589 - User::load
  6.51% 3399.933   1874 - Flow\Templating::getContent
  6.47% 3377.960   4344 - PageTranslationHooks::renderTagPage
  6.43% 3358.321   4347 - TranslatablePage::isTranslationPage
  6.37% 3326.952   4347 - MessageHandle::getKey
  6.37% 3325.755   8694 - MessageHandle::figureMessage
  6.29% 3286.197   4347 - MessageIndex::getGroupIds
  6.24% 3260.901   1777 - ChangesList::showCharacterDifference
  6.19% 3232.705   4347 - DatabaseMessageIndex::get
  6.09% 3179.488   1030 - User::loadFromId
  5.58% 2913.370  30558 - BagOStuff::get
  5.49% 2868.767   2420 - Flow\Data\Compactor\ShallowCompactor::expandCacheResult
  5.44% 2839.643  30520 - Flow\Data\BagOStuff\LocalBufferedBagOStuff::doGet
  5.42% 2831.452  53265 - Flow\FlowActions::getValue
  5.30% 2768.369  30520 - Flow\Data\BagOStuff\BufferedBagOStuff::doGet
  5.17% 2703.079   7372 - Title::isKnown
  5.09% 2660.662    671 - Flow\Formatter\ChangesListFormatter::getTitleLink
  5.07% 2647.492    671 - Flow\Formatter\AbstractFormatter::getTitleLink
  4.98% 2603.363   2420 - Flow\Data\Index\FeatureIndex::findMulti@1
  4.97% 2598.044      1 - ChangesList::initChangesListRows
  4.97% 2598.014      1 - FlowHooks::onChangesListInitRows
  4.97% 2596.722      1 - Flow\Formatter\ChangesListQuery::loadMetadataBatch
  4.96% 2593.337   9358 - Flow\RevisionActionPermissions::getRoot
  4.95% 2584.212   4752 - BagOStuff::get@1
  4.92% 2571.334   4764 - MemcachedBagOStuff::doGet
  4.89% 2557.126   4764 - MemcachedPeclBagOStuff::getWithToken
  4.85% 2534.588   7447 - Title::isAlwaysKnown
  4.84% 2527.556   4249 - section.query: SELECT page_namespace,page_title,page_id,page_len,page_is_redirect,page_latest,page_content_model FROM `page` WHERE page_id = 'X' LIMIT N  [TRX#c15b548e1f5c]
  4.75% 2483.689   1382 - Linker::userLink
  4.64% 2425.603  17469 - User::getName
  4.57% 2386.340  57972 - Message::replaceParameters
  4.57% 2385.669   7447 - GlobalUserPageHooks::onTitleIsAlwaysKnown
  4.55% 2376.092   4347 - section.query: SELECT tmi_value FROM `translate_messageindex` WHERE tmi_key = 'X' LIMIT N  [TRX#c15b548e1f5c]
  4.54% 2373.464   7448 - GlobalUserPage::shouldDisplayGlobalPage
  4.46% 2330.004   4510 - Parser::replaceVariables
  3.99% 2086.708    610 - Flow\Data\ManagerGroup::call
  3.95% 2064.285   2469 - User::__toString
  3.87% 2020.173   1184 - ChangesList::formatCharacterDifference
  3.52% 1840.594      1 - Flow\Formatter\AbstractQuery::loadMetadataBatch
  3.51% 1834.969   1382 - Linker::userToolLinks
...
Bawolff added a comment.Oct 31 2015, 12:18 AM

> 46.85% 24476.879 10798 - Flow\RevisionActionPermissions::isAllowed

Without knowing anything about flow internals, spending 45% of the time verifying permissions seems a lot. Especially for something that's just a view action not a modification action. Perhaps that can be optimized or cached.

Base subscribed.Nov 16 2015, 1:25 PM
Restricted Application added a subscriber: StudiesWorld. · View Herald TranscriptNov 16 2015, 1:25 PM
Reedy mentioned this in T176033: Watchlist param days=30 doesn't override user preference 'watchlistdays' = 0.Nov 19 2017, 9:29 AM
Restricted Application added a project: Growth-Team. · View Herald TranscriptSep 8 2018, 1:33 AM
MBinder_WMF added a project: Growth-Team-Filtering.Apr 15 2021, 7:00 PM
Aklapper removed a project: Collaboration-Team-Triage.May 25 2021, 9:09 PM
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