Page MenuHomePhabricator
Create Task
Maniphest T311360

RecentChanges timing out
Closed, ResolvedPublicPRODUCTION ERROR
Actions

Assigned To
Ladsgroup
Authored By
Zabe
Jun 26 2022, 12:34 PM
Tags
Referenced Files
F35277548: T311360.png
Jun 26 2022, 4:14 PM
Subscribers
1234qwer1234qwer4
Aklapper
Base
BRPever
Johannnes89
kostajh
Ladsgroup
View All 21 Subscribers
Tokens
"Party Time" token, awarded by Tulsi_Bhagat."Cookie" token, awarded by TheresNoTime.

Description

Currently when visiting https://meta.wikimedia.org/wiki/Special:RecentChanges it regularly times out with This search has timed out. You may wish to try different search parameters., this was reported by multiple users.

I found two errors in logstash, which look related.

normalized_message
[{reqId}] {exception_url}   Wikimedia\Rdbms\DBQueryTimeoutError: A database query timeout has occurred. 
Query: SET STATEMENT max_statement_time=30 FOR SELECT  rc_id,rc_timestamp,rc_namespace,rc_title,rc_minor,rc_bot,rc_new,rc_cur_id,rc_this_oldid,rc_last
exception.trace
from /srv/mediawiki/php-1.39.0-wmf.17/includes/libs/rdbms/database/Database.php(1918)
#0 /srv/mediawiki/php-1.39.0-wmf.17/includes/libs/rdbms/database/Database.php(1906): Wikimedia\Rdbms\Database->getQueryException(string, integer, string, string)
#1 /srv/mediawiki/php-1.39.0-wmf.17/includes/libs/rdbms/database/Database.php(1880): Wikimedia\Rdbms\Database->getQueryExceptionAndLog(string, integer, string, string)
#2 /srv/mediawiki/php-1.39.0-wmf.17/includes/libs/rdbms/database/Database.php(1256): Wikimedia\Rdbms\Database->reportQueryError(string, integer, string, string, boolean)
#3 /srv/mediawiki/php-1.39.0-wmf.17/includes/libs/rdbms/database/Database.php(2012): Wikimedia\Rdbms\Database->query(string, string, integer)
#4 /srv/mediawiki/php-1.39.0-wmf.17/includes/libs/rdbms/database/DBConnRef.php(68): Wikimedia\Rdbms\Database->select(array, array, array, string, array, array)
#5 /srv/mediawiki/php-1.39.0-wmf.17/includes/libs/rdbms/database/DBConnRef.php(286): Wikimedia\Rdbms\DBConnRef->__call(string, array)
#6 /srv/mediawiki/php-1.39.0-wmf.17/includes/specials/SpecialRecentChanges.php(431): Wikimedia\Rdbms\DBConnRef->select(array, array, array, string, array, array)
#7 /srv/mediawiki/php-1.39.0-wmf.17/includes/specialpage/ChangesListSpecialPage.php(918): SpecialRecentChanges->doMainQuery(array, array, array, array, array, FormOptions)
#8 /srv/mediawiki/php-1.39.0-wmf.17/includes/specialpage/ChangesListSpecialPage.php(614): ChangesListSpecialPage->getRows()
#9 /srv/mediawiki/php-1.39.0-wmf.17/includes/specials/SpecialRecentChanges.php(206): ChangesListSpecialPage->execute(NULL)
#10 /srv/mediawiki/php-1.39.0-wmf.17/includes/specialpage/SpecialPage.php(688): SpecialRecentChanges->execute(NULL)
#11 /srv/mediawiki/php-1.39.0-wmf.17/includes/specialpage/SpecialPageFactory.php(1418): SpecialPage->run(NULL)
#12 /srv/mediawiki/php-1.39.0-wmf.17/includes/MediaWiki.php(316): MediaWiki\SpecialPage\SpecialPageFactory->executePath(string, RequestContext)
#13 /srv/mediawiki/php-1.39.0-wmf.17/includes/MediaWiki.php(916): MediaWiki->performRequest()
#14 /srv/mediawiki/php-1.39.0-wmf.17/includes/MediaWiki.php(570): MediaWiki->main()
#15 /srv/mediawiki/php-1.39.0-wmf.17/index.php(50): MediaWiki->run()
#16 /srv/mediawiki/php-1.39.0-wmf.17/index.php(46): wfIndexMain()
#17 /srv/mediawiki/w/index.php(3): require(string)
#18 {main}
normalized_message
[{reqId}] {exception_url}   PHP Deprecated: Caller from MediaWiki\Extension\Translate\MessageGroupProcessing\RevTagStore::getLatestRevisionWithTag ignored an error originally raised from SpecialRecentChanges::doMainQuery: [1969] Query execution was interr
exception.trace
from /srv/mediawiki/php-1.39.0-wmf.17/includes/debug/MWDebug.php(381)
#0 [internal function]: MWExceptionHandler::handleError(integer, string, string, integer, array)
#1 /srv/mediawiki/php-1.39.0-wmf.17/includes/debug/MWDebug.php(381): trigger_error(string, integer)
#2 /srv/mediawiki/php-1.39.0-wmf.17/includes/db/MWLBFactory.php(439): MWDebug::sendRawDeprecated(string, boolean, string)
#3 [internal function]: MWLBFactory::logDeprecation(string)
#4 /srv/mediawiki/php-1.39.0-wmf.17/includes/libs/rdbms/database/TransactionManager.php(216): call_user_func(array, string)
#5 /srv/mediawiki/php-1.39.0-wmf.17/includes/libs/rdbms/database/Database.php(1697): Wikimedia\Rdbms\TransactionManager->assertTransactionStatus(Wikimedia\Rdbms\DatabaseMysqli, array, string)
#6 /srv/mediawiki/php-1.39.0-wmf.17/includes/libs/rdbms/database/Database.php(1240): Wikimedia\Rdbms\Database->assertQueryIsCurrentlyAllowed(string, string)
#7 /srv/mediawiki/php-1.39.0-wmf.17/includes/libs/rdbms/database/Database.php(2012): Wikimedia\Rdbms\Database->query(string, string, integer)
#8 /srv/mediawiki/php-1.39.0-wmf.17/includes/libs/rdbms/database/Database.php(1965): Wikimedia\Rdbms\Database->select(string, string, array, string, array, array)
#9 /srv/mediawiki/php-1.39.0-wmf.17/includes/libs/rdbms/database/DBConnRef.php(68): Wikimedia\Rdbms\Database->selectField(string, string, array, string, array)
#10 /srv/mediawiki/php-1.39.0-wmf.17/includes/libs/rdbms/database/DBConnRef.php(273): Wikimedia\Rdbms\DBConnRef->__call(string, array)
#11 /srv/mediawiki/php-1.39.0-wmf.17/extensions/Translate/src/MessageGroupProcessing/RevTagStore.php(70): Wikimedia\Rdbms\DBConnRef->selectField(string, string, array, string, array)
#12 /srv/mediawiki/php-1.39.0-wmf.17/extensions/Translate/tag/TranslatablePage.php(322): MediaWiki\Extension\Translate\MessageGroupProcessing\RevTagStore->getLatestRevisionWithTag(Title, string)
#13 /srv/mediawiki/php-1.39.0-wmf.17/extensions/Translate/tag/TranslatablePage.php(524): TranslatablePage->getMarkedTag()
#14 /srv/mediawiki/php-1.39.0-wmf.17/extensions/Translate/tag/PageTranslationHooks.php(189): TranslatablePage::isTranslationPage(Title)
#15 /srv/mediawiki/php-1.39.0-wmf.17/includes/HookContainer/HookContainer.php(338): PageTranslationHooks::fetchTranslatableTemplateAndTitle(Title, Title, boolean, NULL)
#16 /srv/mediawiki/php-1.39.0-wmf.17/includes/HookContainer/HookContainer.php(137): MediaWiki\HookContainer\HookContainer->callLegacyHook(string, array, array, array)
#17 /srv/mediawiki/php-1.39.0-wmf.17/includes/HookContainer/HookRunner.php(978): MediaWiki\HookContainer\HookContainer->run(string, array)
#18 /srv/mediawiki/php-1.39.0-wmf.17/includes/parser/Parser.php(3684): MediaWiki\HookContainer\HookRunner->onBeforeParserFetchTemplateRevisionRecord(Title, Title, boolean, NULL)
#19 /srv/mediawiki/php-1.39.0-wmf.17/includes/parser/Parser.php(3620): Parser->statelessFetchTemplate(Title, Parser)
#20 /srv/mediawiki/php-1.39.0-wmf.17/includes/parser/Parser.php(3513): Parser->fetchTemplateAndTitle(Title)
#21 /srv/mediawiki/php-1.39.0-wmf.17/includes/parser/Parser.php(3252): Parser->getTemplateDom(Title)
#22 /srv/mediawiki/php-1.39.0-wmf.17/includes/parser/PPFrame_Hash.php(276): Parser->braceSubstitution(array, PPFrame_Hash)
#23 /srv/mediawiki/php-1.39.0-wmf.17/includes/parser/Parser.php(2971): PPFrame_Hash->expand(PPNode_Hash_Tree, integer)
#24 /srv/mediawiki/php-1.39.0-wmf.17/includes/parser/Parser.php(1607): Parser->replaceVariables(string)
#25 /srv/mediawiki/php-1.39.0-wmf.17/includes/parser/Parser.php(723): Parser->internalParse(string)
#26 /srv/mediawiki/php-1.39.0-wmf.17/includes/cache/MessageCache.php(1335): Parser->parse(string, Title, ParserOptions, boolean)
#27 /srv/mediawiki/php-1.39.0-wmf.17/includes/specials/SpecialRecentChanges.php(736): MessageCache->parse(string, Title, boolean, boolean, LanguageEn)
#28 /srv/mediawiki/php-1.39.0-wmf.17/includes/specials/SpecialRecentChanges.php(620): SpecialRecentChanges->setTopText(FormOptions)
#29 /srv/mediawiki/php-1.39.0-wmf.17/includes/specialpage/ChangesListSpecialPage.php(1541): SpecialRecentChanges->doHeader(FormOptions, integer)
#30 /srv/mediawiki/php-1.39.0-wmf.17/includes/specialpage/ChangesListSpecialPage.php(668): ChangesListSpecialPage->webOutputHeader(integer, FormOptions)
#31 /srv/mediawiki/php-1.39.0-wmf.17/includes/specials/SpecialRecentChanges.php(206): ChangesListSpecialPage->execute(NULL)
#32 /srv/mediawiki/php-1.39.0-wmf.17/includes/specialpage/SpecialPage.php(688): SpecialRecentChanges->execute(NULL)
#33 /srv/mediawiki/php-1.39.0-wmf.17/includes/specialpage/SpecialPageFactory.php(1418): SpecialPage->run(NULL)
#34 /srv/mediawiki/php-1.39.0-wmf.17/includes/MediaWiki.php(316): MediaWiki\SpecialPage\SpecialPageFactory->executePath(string, RequestContext)
#35 /srv/mediawiki/php-1.39.0-wmf.17/includes/MediaWiki.php(916): MediaWiki->performRequest()
#36 /srv/mediawiki/php-1.39.0-wmf.17/includes/MediaWiki.php(570): MediaWiki->main()
#37 /srv/mediawiki/php-1.39.0-wmf.17/index.php(50): MediaWiki->run()
#38 /srv/mediawiki/php-1.39.0-wmf.17/index.php(46): wfIndexMain()
#39 /srv/mediawiki/w/index.php(3): require(string)
#40 {main}

T311360.png (249×673 px, 13 KB)

Example timing out SQL query:

SET STATEMENT max_statement_time=30 FOR SELECT  rc_id,rc_timestamp,rc_namespace,rc_title,rc_minor,rc_bot,rc_new,rc_cur_id,rc_this_oldid,rc_last_oldid,rc_type,rc_source,rc_patrolled,rc_ip,rc_old_len,rc_new_len,rc_deleted,rc_logid,rc_log_type,rc_log_action,rc_params,rc_actor,recentchanges_actor.actor_user AS `rc_user`,recentchanges_actor.actor_name AS `rc_user_text`,comment_rc_comment.comment_text AS `rc_comment_text`,comment_rc_comment.comment_data AS `rc_comment_data`,comment_rc_comment.comment_id AS `rc_comment_cid`,rc_title,rc_namespace,wl_user,wl_notificationtimestamp,we_expiry,page_latest,(SELECT  GROUP_CONCAT(ctd_name SEPARATOR ',')  FROM `change_tag` JOIN `change_tag_def` ON ((ct_tag_id=ctd_id))   WHERE ct_rc_id=rc_id  ) AS `ts_tags`  FROM `recentchanges` JOIN `actor` `recentchanges_actor` ON ((actor_id=rc_actor)) JOIN `comment` `comment_rc_comment` ON ((comment_rc_comment.comment_id = rc_comment_id)) LEFT JOIN `watchlist` ON (wl_user = {redacted} AND (wl_title=rc_title) AND (wl_namespace=rc_namespace)) LEFT JOIN `watchlist_expiry` ON ((wl_id = we_item)) LEFT JOIN `page` ON ((rc_cur_id=page_id))   WHERE rc_bot = 0 AND (rc_type != 6) AND (rc_source != 'wb') AND (rc_namespace NOT IN (1198,1199,866,867)) AND (rc_timestamp >= '20220625123404') AND rc_new IN (0,1)   ORDER BY rc_timestamp DESC LIMIT 50

And the EXPLAIN on that query:

+------+--------------------+---------------------+--------+-----------------------------------------------------------------------------------------------------------------------+--------------+---------+---------------------------------------------------------------------------+----------+------------------------------------+
| id   | select_type        | table               | type   | possible_keys                                                                                                         | key          | key_len | ref                                                                       | rows     | Extra                              |
+------+--------------------+---------------------+--------+-----------------------------------------------------------------------------------------------------------------------+--------------+---------+---------------------------------------------------------------------------+----------+------------------------------------+
|    1 | PRIMARY            | recentchanges_actor | ALL    | PRIMARY                                                                                                               | NULL         | NULL    | NULL                                                                      | 32355775 | Using temporary; Using filesort    |
|    1 | PRIMARY            | recentchanges       | ref    | rc_timestamp,rc_name_type_patrolled_timestamp,rc_ns_actor,rc_actor,rc_namespace_title_timestamp,rc_new_name_timestamp | rc_actor     | 8       | metawiki.recentchanges_actor.actor_id                                     | 19       | Using index condition; Using where |
|    1 | PRIMARY            | comment_rc_comment  | eq_ref | PRIMARY                                                                                                               | PRIMARY      | 8       | metawiki.recentchanges.rc_comment_id                                      | 1        |                                    |
|    1 | PRIMARY            | watchlist           | eq_ref | wl_user,wl_user_notificationtimestamp,wl_namespace_title                                                              | wl_user      | 265     | const,metawiki.recentchanges.rc_namespace,metawiki.recentchanges.rc_title | 1        |                                    |
|    1 | PRIMARY            | watchlist_expiry    | eq_ref | PRIMARY                                                                                                               | PRIMARY      | 4       | metawiki.watchlist.wl_id                                                  | 1        | Using where                        |
|    1 | PRIMARY            | page                | eq_ref | PRIMARY                                                                                                               | PRIMARY      | 4       | metawiki.recentchanges.rc_cur_id                                          | 1        |                                    |
|    3 | DEPENDENT SUBQUERY | change_tag          | ref    | ct_rc_tag_id,ct_tag_id_id                                                                                             | ct_rc_tag_id | 5       | metawiki.recentchanges.rc_id                                              | 1        | Using index                        |
|    3 | DEPENDENT SUBQUERY | change_tag_def      | eq_ref | PRIMARY                                                                                                               | PRIMARY      | 4       | metawiki.change_tag.ct_tag_id                                             | 1        |                                    |
+------+--------------------+---------------------+--------+-----------------------------------------------------------------------------------------------------------------------+--------------+---------+---------------------------------------------------------------------------+----------+------------------------------------+
8 rows in set (0.002 sec)

List of steps to reproduce (step by step, including full links if applicable):

What happens?:

  • No results are returned
  • Error message: This search has timed out. You may wish to try different search parameters.

What should have happened instead?:

  • The recent changes should be displayed

Software version (if not a Wikimedia wiki), browser information, screenshots, other information, etc.:
This is happening logged in or logged out, multiple browsers

Upstream MariaDB bug: MDEV-28984 - Optimizer picking the wrong table for order of join

Details

SubjectRepoBranchLines +/-
RecentChange: Straight join to actor table when neededmediawiki/coreREL1_37+9 -1
RecentChange: Make join to comment table also straightmediawiki/coreREL1_37+2 -0
RecentChange: Make join to comment table also straightmediawiki/coreREL1_38+2 -0
RecentChange: Straight join to actor table when neededmediawiki/coreREL1_38+9 -1
RecentChange: Make join to comment table also straightmediawiki/corewmf/1.39.0-wmf.18+2 -0
Revert "Revert "RecentChange: Straight join to actor table when needed""mediawiki/corewmf/1.39.0-wmf.18+9 -1
RecentChange: Make join to comment table also straightmediawiki/coremaster+2 -0
RecentChange: Straight join to actor table when neededmediawiki/corewmf/1.39.0-wmf.18+9 -1
RecentChange: Straight join to actor table when neededmediawiki/coremaster+9 -1
specials: Move condition from JOIN ... ON to WHEREmediawiki/coremaster+1 -1
Customize query in gerrit

Related Objects

Event Timeline

There are a very large number of changes, so older changes are hidden. Show Older Changes
Mykola7 subscribed.Jun 28 2022, 1:08 PM
Base subscribed.Jun 28 2022, 2:45 PM
SpartacksCompatriot subscribed.Jun 28 2022, 3:26 PM
MarcoAurelio subscribed.Jun 29 2022, 9:25 AM
BRPever subscribed.Jun 29 2022, 12:08 PM
Xaosflux added a comment.Jun 29 2022, 1:56 PM

This outage is continuing, do we need volunteers or staff to work on this?

1234qwer1234qwer4 subscribed.Jun 29 2022, 2:56 PM
1234qwer1234qwer4 added a comment.Jun 29 2022, 3:15 PM
In T311360#8027523, @Nikerabbit wrote:

I assume MediaWiki-extensions-Translate was tagged because of this, but there is no code that ignores errors there. My guess is that it just happens to be the next query executed after the query that was interrupted by the timeout and that Special:RecentChanges is the one ignoring that error.

Note that translation unit deletions have been being stuck in the job queue indefinitely (?) the last days, though I have no clue whether that could be related.

TheresNoTime moved this task from Untriaged to Jun 2022 on the Wikimedia-production-error board.Jun 29 2022, 3:19 PM
TheresNoTime changed the subtype of this task from "Task" to "Production Error".
Johannnes89 subscribed.Jun 29 2022, 3:39 PM
sbassett added a project: Vuln-DoS.Jun 29 2022, 3:39 PM
Minorax subscribed.Jun 29 2022, 4:06 PM
TheresNoTime added a comment.Jun 29 2022, 4:24 PM

62 instances of [{reqId}] {exception_url} Wikimedia\Rdbms\DBQueryTimeoutError: A database query timeout has occurred. Query: SET STATEMENT max_statement_time=30 FOR SELECT rc_id,rc_timestamp,rc_namespace,rc_title,rc_minor,rc_bot,rc_new,rc_cur_id,rc_this_oldid,rc_last in the last 1 hour.

Looking at the last 7 days, this is heavily skewed towards affecting metawiki

server #
meta.wikimedia.org4,572
www.mediawiki.org1,718
en.wikipedia.org275
de.wikipedia.org108
www.wikidata.org62
Zabe added projects: Platform Engineering, DBA.EditedJun 29 2022, 4:52 PM

Also see T304482. Adding DBA since this might be mariadb another optimizer bug.

Trizek-WMF subscribed.Jun 29 2022, 6:57 PM
kostajh updated the task description. (Show Details)Jun 29 2022, 7:26 PM
kostajh updated the task description. (Show Details)Jun 29 2022, 7:29 PM
kostajh added a project: Performance-Team.Jun 29 2022, 7:37 PM
Ladsgroup subscribed.Jun 29 2022, 7:43 PM

The order of join is wrong, it should be rc table first and then actor table. Technically this is optimizer bug but I'm not following why it's happening only on metawiki. Let me optimize the table to see if that fixes it.

TheresNoTime awarded a token.Jun 29 2022, 7:44 PM
Ladsgroup added a comment.Jun 29 2022, 7:48 PM

I optimized both rc and actor in db2108 and the result was the same

Umherirrender added a project: Wikimedia-Slow-DB-Query.Jun 29 2022, 8:06 PM
Ladsgroup added a comment.Jun 29 2022, 8:08 PM

Now did alter table as well but no change. This is also seen in both 10.4 and 10.6 :/

Ladsgroup added a project: mariadb-optimizer-bug.Jun 29 2022, 8:09 PM
Ladsgroup added a comment.Jun 29 2022, 8:16 PM

Strangely, making the query more standard (moving the condition from join to WHERE) actually fixes the issue. For reasons unknown to me.

gerritbot added a comment.Jun 29 2022, 8:19 PM

Change 809680 had a related patch set uploaded (by Ladsgroup; author: Amir Sarabadani):

[mediawiki/core@master] specials: Move condition from JOIN ... ON to WHERE

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

gerritbot added a project: Patch-For-Review.Jun 29 2022, 8:19 PM
Ladsgroup claimed this task.Jun 29 2022, 8:28 PM
Ladsgroup moved this task from Triage to In progress on the DBA board.

This fixes it, tested on mwdebug1001.

I think we probably should report it to upstream as well. This is quite weird, there is no condition nor order nor group by is in actor table but somehow optimizer thinks it's a great idea to pick it.

Ladsgroup added a project: Upstream.Jun 29 2022, 9:42 PM

The watchlist part was a red herring. I reported it upstream https://jira.mariadb.org/browse/MDEV-28984

gerritbot added a comment.Jun 29 2022, 9:43 PM

Change 809680 abandoned by Ladsgroup:

[mediawiki/core@master] specials: Move condition from JOIN ... ON to WHERE

Reason:

won't fix the problem

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

Maintenance_bot removed a project: Patch-For-Review.Jun 29 2022, 10:30 PM
Marostegui subscribed.Jun 30 2022, 8:35 AM
In T311360#8038618, @Ladsgroup wrote:

The watchlist part was a red herring. I reported it upstream https://jira.mariadb.org/browse/MDEV-28984

Thanks for reporting it.

kostajh added a comment.Jun 30 2022, 8:46 AM
In T311360#8038621, @gerritbot wrote:

Change 809680 abandoned by Ladsgroup:

[mediawiki/core@master] specials: Move condition from JOIN ... ON to WHERE

Reason:

won't fix the problem

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

@Ladsgroup do you have thoughts on what we can do to mitigate the problem in the meantime?

Ladsgroup added a comment.Jun 30 2022, 10:09 AM

So adding straight join would fix it but it would break anything that has a filter on anything that's not in rc table. For example, for a similar situation in logging table, adding straight join break everything that filters based on user (because you have to turn that into actor id). The only case I can think of here is ores filters but I'm missing something. Let me check and then I make the patch. Unfortunately, the current rdbms library doesn't allow to have "one" straight join (e.g. between rc and actor which is possible in mariadb) but it would make all joins straight which is dangerous.

I also don't understand why actor migration was done on rc table. It's the denomarlization table of mediawiki. Anyway, the ship has sailed.

Ladsgroup added a comment.Jun 30 2022, 11:08 AM

It seems the straight join for one-table-only works (it might have been broken/recently added/etc.) but at the same time, there are filters that explicitly condition on actor table. Like the one that looks for newcomers/non-users/hide-not-me/hide-me/... so doing straight join on actor would break all of those.

gerritbot added a comment.Jun 30 2022, 4:19 PM

Change 810051 had a related patch set uploaded (by Ladsgroup; author: Amir Sarabadani):

[mediawiki/core@master] RecentChange: Straight join to actor table when needed

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

gerritbot added a project: Patch-For-Review.Jun 30 2022, 4:19 PM
Ladsgroup added a comment.Jun 30 2022, 4:26 PM

^ It is horrible but it works

gerritbot added a comment.Jun 30 2022, 5:06 PM

Change 810051 merged by jenkins-bot:

[mediawiki/core@master] RecentChange: Straight join to actor table when needed

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

Maintenance_bot removed a project: Patch-For-Review.Jun 30 2022, 5:29 PM
gerritbot added a comment.Jun 30 2022, 7:09 PM

Change 809959 had a related patch set uploaded (by Stang; author: Amir Sarabadani):

[mediawiki/core@wmf/1.39.0-wmf.18] RecentChange: Straight join to actor table when needed

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

gerritbot added a project: Patch-For-Review.Jun 30 2022, 7:09 PM
gerritbot added a comment.Jun 30 2022, 8:58 PM

Change 809959 merged by jenkins-bot:

[mediawiki/core@wmf/1.39.0-wmf.18] RecentChange: Straight join to actor table when needed

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

Stang added a comment.Jun 30 2022, 9:06 PM

Backported, but my test on mwdebug1002 sadly shows this issue still exist...

Zabe added a comment.Jun 30 2022, 9:11 PM
[e63a6c70-26b5-4b1f-b807-3f39c105554d] /wiki/Special:RecentChanges?hidebots=1&translations=filter&hidecategorization=1&hideWikibase=1&limit=50&days=7&urlversion=2   Wikimedia\Rdbms\DBQueryTimeoutError: A database query timeout has occurred. 
Query: SET STATEMENT max_statement_time=30 FOR SELECT  rc_id,rc_timestamp,rc_namespace,rc_title,rc_minor,rc_bot,rc_new,rc_cur_id,rc_this_oldid,rc_last_oldid,rc_type,rc_source,rc_patrolled,rc_ip,rc_old_len,rc_new_len,rc_deleted,rc_logid,rc_log_type,rc_log_action,rc_params,rc_actor,recentchanges_actor.actor_user AS `rc_user`,recentchanges_actor.actor_name AS `rc_user_text`,comment_rc_comment.comment_text AS `rc_comment_text`,comment_rc_comment.comment_data AS `rc_comment_data`,comment_rc_comment.comment_id AS `rc_comment_cid`,rc_title,rc_namespace,page_latest,(SELECT  GROUP_CONCAT(ctd_name SEPARATOR ',')  FROM `change_tag` JOIN `change_tag_def` ON ((ct_tag_id=ctd_id))   WHERE ct_rc_id=rc_id  ) AS `ts_tags`  FROM `recentchanges` STRAIGHT_JOIN `actor` `recentchanges_actor` ON ((actor_id=rc_actor)) JOIN `comment` `comment_rc_comment` ON ((comment_rc_comment.comment_id = rc_comment_id)) LEFT JOIN `page` ON ((rc_cur_id=page_id))   WHERE rc_bot = 0 AND (rc_type != 6) AND (rc_source != 'wb') AND (rc_namespace NOT IN (1198,1199,866,867)) AND (rc_timestamp >= '20220623210517') AND rc_new IN (0,1)   ORDER BY rc_timestamp DESC LIMIT 50  
Function: SpecialRecentChanges::doMainQuery
Error: 1969 Query execution was interrupted (max_statement_time exceeded)
Ladsgroup added a comment.Jun 30 2022, 9:29 PM
MariaDB [metawiki]> explain SELECT  rc_id,rc_timestamp,rc_namespace,rc_title,rc_minor,rc_bot,rc_new,rc_cur_id,rc_this_oldid,rc_last_oldid,rc_type,rc_source,rc_patrolled,rc_ip,rc_old_len,rc_new_len,rc_deleted,rc_logid,rc_log_type,rc_log_action,rc_params,rc_actor,recentchanges_actor.actor_user AS `rc_user`,recentchanges_actor.actor_name AS `rc_user_text`,comment_rc_comment.comment_text AS `rc_comment_text`,comment_rc_comment.comment_data AS `rc_comment_data`,comment_rc_comment.comment_id AS `rc_comment_cid`,rc_title,rc_namespace,page_latest,(SELECT  GROUP_CONCAT(ctd_name SEPARATOR ',')  FROM `change_tag` JOIN `change_tag_def` ON ((ct_tag_id=ctd_id))   WHERE ct_rc_id=rc_id  ) AS `ts_tags`  FROM `recentchanges` STRAIGHT_JOIN `actor` `recentchanges_actor` ON ((actor_id=rc_actor)) JOIN `comment` `comment_rc_comment` ON ((comment_rc_comment.comment_id = rc_comment_id)) LEFT JOIN `page` ON ((rc_cur_id=page_id))   WHERE rc_bot = 0 AND (rc_type != 6) AND (rc_source != 'wb') AND (rc_namespace NOT IN (1198,1199,866,867)) AND (rc_timestamp >= '20220623210517') AND rc_new IN (0,1)   ORDER BY rc_timestamp DESC LIMIT 50  ;
+------+--------------------+---------------------+----------+-----------------------------------------------------------------------------------------------------------------------+--------------+---------+----------------------------------------+---------+--------------------------------------------------+
| id   | select_type        | table               | type     | possible_keys                                                                                                         | key          | key_len | ref                                    | rows    | Extra                                            |
+------+--------------------+---------------------+----------+-----------------------------------------------------------------------------------------------------------------------+--------------+---------+----------------------------------------+---------+--------------------------------------------------+
|    1 | PRIMARY            | comment_rc_comment  | ALL      | PRIMARY                                                                                                               | NULL         | NULL    | NULL                                   | 5513374 | Using temporary; Using filesort                  |
|    1 | PRIMARY            | recentchanges       | hash_ALL | rc_timestamp,rc_name_type_patrolled_timestamp,rc_ns_actor,rc_actor,rc_namespace_title_timestamp,rc_new_name_timestamp | #hash#$hj    | 8       | metawiki.comment_rc_comment.comment_id | 203986  | Using where; Using join buffer (flat, BNLH join) |
|    1 | PRIMARY            | page                | eq_ref   | PRIMARY                                                                                                               | PRIMARY      | 4       | metawiki.recentchanges.rc_cur_id       | 1       |                                                  |
|    1 | PRIMARY            | recentchanges_actor | eq_ref   | PRIMARY                                                                                                               | PRIMARY      | 8       | metawiki.recentchanges.rc_actor        | 1       |                                                  |
|    2 | DEPENDENT SUBQUERY | change_tag          | ref      | ct_rc_tag_id,ct_tag_id_id                                                                                             | ct_rc_tag_id | 5       | metawiki.recentchanges.rc_id           | 1       | Using index                                      |
|    2 | DEPENDENT SUBQUERY | change_tag_def      | eq_ref   | PRIMARY                                                                                                               | PRIMARY      | 4       | metawiki.change_tag.ct_tag_id          | 1       |                                                  |
+------+--------------------+---------------------+----------+-----------------------------------------------------------------------------------------------------------------------+--------------+---------+----------------------------------------+---------+--------------------------------------------------+

sigh....

Thankfully we don't have anything that would possibly condition on comment table, so a direct straight join would work here.

And it seems to work:

MariaDB [metawiki]> explain SELECT  rc_id,rc_timestamp,rc_namespace,rc_title,rc_minor,rc_bot,rc_new,rc_cur_id,rc_this_oldid,rc_last_oldid,rc_type,rc_source,rc_patrolled,rc_ip,rc_old_len,rc_new_len,rc_deleted,rc_logid,rc_log_type,rc_log_action,rc_params,rc_actor,recentchanges_actor.actor_user AS `rc_user`,recentchanges_actor.actor_name AS `rc_user_text`,comment_rc_comment.comment_text AS `rc_comment_text`,comment_rc_comment.comment_data AS `rc_comment_data`,comment_rc_comment.comment_id AS `rc_comment_cid`,rc_title,rc_namespace,page_latest,(SELECT  GROUP_CONCAT(ctd_name SEPARATOR ',')  FROM `change_tag` JOIN `change_tag_def` ON ((ct_tag_id=ctd_id))   WHERE ct_rc_id=rc_id  ) AS `ts_tags`  FROM `recentchanges` STRAIGHT_JOIN `actor` `recentchanges_actor` ON ((actor_id=rc_actor)) STRAIGHT_JOIN `comment` `comme                                                                                                                                                                                                      119
+------+--------------------+---------------------+--------+-----------------------------------------------------------------------------------------------------------------------+--------------+---------+--------------------------------------+--------+-------------+
| id   | select_type        | table               | type   | possible_keys                                                                                                         | key          | key_len | ref                                  | rows   | Extra       |
+------+--------------------+---------------------+--------+-----------------------------------------------------------------------------------------------------------------------+--------------+---------+--------------------------------------+--------+-------------+
|    1 | PRIMARY            | recentchanges       | range  | rc_timestamp,rc_name_type_patrolled_timestamp,rc_ns_actor,rc_actor,rc_namespace_title_timestamp,rc_new_name_timestamp | rc_timestamp | 14      | NULL                                 | 101995 | Using where |
|    1 | PRIMARY            | recentchanges_actor | eq_ref | PRIMARY                                                                                                               | PRIMARY      | 8       | metawiki.recentchanges.rc_actor      | 1      |             |
|    1 | PRIMARY            | comment_rc_comment  | eq_ref | PRIMARY                                                                                                               | PRIMARY      | 8       | metawiki.recentchanges.rc_comment_id | 1      |             |
|    1 | PRIMARY            | page                | eq_ref | PRIMARY                                                                                                               | PRIMARY      | 4       | metawiki.recentchanges.rc_cur_id     | 1      |             |
|    2 | DEPENDENT SUBQUERY | change_tag          | ref    | ct_rc_tag_id,ct_tag_id_id                                                                                             | ct_rc_tag_id | 5       | metawiki.recentchanges.rc_id         | 1      | Using index |
|    2 | DEPENDENT SUBQUERY | change_tag_def      | eq_ref | PRIMARY                                                                                                               | PRIMARY      | 4       | metawiki.change_tag.ct_tag_id        | 1      |             |
+------+--------------------+---------------------+--------+-----------------------------------------------------------------------------------------------------------------------+--------------+---------+--------------------------------------+--------+-------------+
6 rows in set (0.002 sec)
Maintenance_bot removed a project: Patch-For-Review.Jun 30 2022, 9:30 PM
gerritbot added a comment.Jun 30 2022, 9:39 PM

Change 810108 had a related patch set uploaded (by Ladsgroup; author: Amir Sarabadani):

[mediawiki/core@master] RecentChange: Make join to comment table also straight

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

gerritbot added a project: Patch-For-Review.Jun 30 2022, 9:39 PM
Ladsgroup added a comment.Jun 30 2022, 9:40 PM

Here comes another not-so-great patch. I don't mind adding optimizer in such cases but the SQL building in mediawiki is ewww. Anyway.

gerritbot added a comment.Jun 30 2022, 10:09 PM

Change 810108 merged by jenkins-bot:

[mediawiki/core@master] RecentChange: Make join to comment table also straight

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

Maintenance_bot removed a project: Patch-For-Review.Jun 30 2022, 10:30 PM
gerritbot added a comment.Jul 1 2022, 1:04 PM

Change 810138 had a related patch set uploaded (by Zabe; author: Amir Sarabadani):

[mediawiki/core@wmf/1.39.0-wmf.18] RecentChange: Make join to comment table also straight

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

gerritbot added a project: Patch-For-Review.Jul 1 2022, 1:04 PM

Change 810139 had a related patch set uploaded (by Zabe; author: Zabe):

[mediawiki/core@wmf/1.39.0-wmf.18] Revert "Revert "RecentChange: Straight join to actor table when needed""

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

RhinosF1 subscribed.Jul 2 2022, 9:56 PM

@Ladsgroup; could these potentially be backported as we're seeing poor performance on RC at Miraheze?

RhinosF1 added a comment.Jul 2 2022, 9:57 PM

See also {T302741}

Marostegui added a comment.Jul 3 2022, 8:46 AM

If that's exactly the same optimizee bug Amir has reported to mariadb, we should also include that 10.5.15 version there

Teles subscribed.Jul 4 2022, 1:14 AM
Tulsi_Bhagat subscribed.Jul 4 2022, 4:16 AM
gerritbot added a comment.Jul 4 2022, 10:34 AM

Change 810139 merged by jenkins-bot:

[mediawiki/core@wmf/1.39.0-wmf.18] Revert "Revert "RecentChange: Straight join to actor table when needed""

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

gerritbot added a comment.Jul 4 2022, 10:34 AM

Change 810138 merged by jenkins-bot:

[mediawiki/core@wmf/1.39.0-wmf.18] RecentChange: Make join to comment table also straight

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

Stashbot added a comment.Jul 4 2022, 10:54 AM

Mentioned in SAL (#wikimedia-operations) [2022-07-04T10:54:55Z] <ladsgroup@deploy1002> Synchronized php-1.39.0-wmf.18/includes: Backport: [[gerrit:810139|Revert "Revert "RecentChange: Straight join to actor table when needed"" (T311360)]] (duration: 03m 49s)

gerritbot added a comment.Jul 4 2022, 10:56 AM

Change 810519 had a related patch set uploaded (by Ladsgroup; author: Amir Sarabadani):

[mediawiki/core@REL1_38] RecentChange: Straight join to actor table when needed

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

gerritbot added a comment.Jul 4 2022, 10:57 AM

Change 810520 had a related patch set uploaded (by Ladsgroup; author: Amir Sarabadani):

[mediawiki/core@REL1_37] RecentChange: Straight join to actor table when needed

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

gerritbot added a comment.Jul 4 2022, 10:57 AM

Change 810521 had a related patch set uploaded (by Ladsgroup; author: Amir Sarabadani):

[mediawiki/core@REL1_38] RecentChange: Make join to comment table also straight

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

gerritbot added a comment.Jul 4 2022, 10:57 AM

Change 810522 had a related patch set uploaded (by Ladsgroup; author: Amir Sarabadani):

[mediawiki/core@REL1_37] RecentChange: Make join to comment table also straight

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

Ciencia_Al_Poder updated the task description. (Show Details)Jul 4 2022, 11:09 AM
gerritbot added a comment.Jul 4 2022, 11:10 AM

Change 810519 merged by jenkins-bot:

[mediawiki/core@REL1_38] RecentChange: Straight join to actor table when needed

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

gerritbot added a comment.Jul 4 2022, 11:10 AM

Change 810521 merged by jenkins-bot:

[mediawiki/core@REL1_38] RecentChange: Make join to comment table also straight

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

Ladsgroup added a comment.EditedJul 4 2022, 12:30 PM

@RhinosF1 backporting the fix for that, requires backporting https://gerrit.wikimedia.org/r/c/mediawiki/core/+/752027 to 1.37 as well and that includes a breaking change. So I don't think we will backport this to 1.37

gerritbot added a comment.Jul 4 2022, 12:31 PM

Change 810522 abandoned by Ladsgroup:

[mediawiki/core@REL1_37] RecentChange: Make join to comment table also straight

Reason:

https://phabricator.wikimedia.org/T311360#8048889

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

gerritbot added a comment.Jul 4 2022, 12:31 PM

Change 810520 abandoned by Ladsgroup:

[mediawiki/core@REL1_37] RecentChange: Straight join to actor table when needed

Reason:

https://phabricator.wikimedia.org/T311360#8048889

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

Ladsgroup closed this task as Resolved.Jul 4 2022, 12:32 PM

This is fixed now.

RhinosF1 added a comment.Jul 4 2022, 12:57 PM
In T311360#8048889, @Ladsgroup wrote:

@RhinosF1 backporting the fix for that, requires backporting https://gerrit.wikimedia.org/r/c/mediawiki/core/+/752027 to 1.37 as well and that includes a breaking change. So I don't think we will backport this to 1.37

We are now 1.38

Maintenance_bot moved this task from In progress to Done on the DBA board.Jul 4 2022, 1:29 PM
Tulsi_Bhagat awarded a token.Jul 5 2022, 9:37 AM
Zabe removed a project: Patch-For-Review.Jul 5 2022, 9:46 AM
1234qwer1234qwer4 added a comment.Jul 7 2022, 9:13 PM
In T311360#8048895, @Ladsgroup wrote:

This is fixed now.

To clarify, is this something yet to be deployed?

Ladsgroup added a comment.Jul 7 2022, 9:29 PM

Nope, it got deployed:

In T311360#8048366, @Stashbot wrote:

Mentioned in SAL (#wikimedia-operations) [2022-07-04T10:54:55Z] <ladsgroup@deploy1002> Synchronized php-1.39.0-wmf.18/includes: Backport: [[gerrit:810139|Revert "Revert "RecentChange: Straight join to actor table when needed"" (T311360)]] (duration: 03m 49s)

1234qwer1234qwer4 added a comment.Jul 7 2022, 9:29 PM

Well, my feed is still timing out: https://meta.wikimedia.org/w/index.php?userExpLevel=unregistered%3Bnewcomer&hidebots=1&translations=filter&hidecategorization=1&hideWikibase=1&limit=500&days=30&reviewStatus__manual_color=c2&changeType__hidelog_color=c3&tagfilter__mw-reverted_color=c1&title=Special:RecentChanges&urlversion=2

Ladsgroup added a comment.Jul 7 2022, 9:35 PM

The task is about the default view of recentchanges without any filters. There is no guarantee that every combination of RC filters will be fast (and some would be slow because of the complexity of the filters) and some has been giving timeout long time ago: T239192

Someone probably can create a similar tool in WMCS with much higher timeout.

If your problem is new, then we need to look into it a bit (and file a separate ticket?)

1234qwer1234qwer4 added a comment.Jul 7 2022, 9:40 PM

I've been using that feed for at least a year without any problems. This started to occur about when this bug was reported.

Johannnes89 added a comment.EditedJul 9 2022, 9:23 AM

+1 my default filter options (looking for latest revisions by IPs/Newbies) are still timing out most of the time and weren't before this bug was reported
https://meta.wikimedia.org/wiki/Special:RecentChanges?userExpLevel=unregistered%3Bnewcomer&hidebots=1&hidepreviousrevisions=1&translations=filter&hidecategorization=1&hideWikibase=1&hidelog=1&limit=50&days=1&urlversion=2

Ladsgroup added a comment.Jul 10 2022, 4:18 PM

It is caused by this straight join being removed when there is a filter on user type (because it conditions on the actor table in some cases it's better to go in the direction of actor -> rc than the other way around). So if you remove that condition, it should be working again (until I find a fix for it).

ReleaseTaggerBot added a project: MW-1.39-notes (1.39.0-wmf.18; 2022-06-27).Jul 11 2022, 11:01 PM
ReleaseTaggerBot added a project: MW-1.38-notes.Jul 12 2022, 1:01 AM
Stang unsubscribed.Jul 15 2022, 4:05 AM
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