Special:RecentChanges with complex query (rc_namespace = 1 AND ct_tag = 'visualeditor') slow due to using wrong index
Open, Needs TriagePublic
Actions

Description

From production.

This is probably another case where there are simply few or no matches, and insufficient indexes (like its parent T164796: Very long search times on RC Page for "Very likely good faith" + "Likely have problems" (on en.wiki only?)). However, in this case, instead of just being slow it times out entirely.

mattflaschen@mwlog1001:~$ grep -A20 WUPWEgpAIDgAAFdx4R8AAAAQ /srv/mw-log/exception.log 
2017-06-16 12:59:58 [WUPWEgpAIDgAAFdx4R8AAAAQ] mw1186 enwiki 1.30.0-wmf.5 exception ERROR: [WUPWEgpAIDgAAFdx4R8AAAAQ] /w/index.php?namespace=1&tagfilter=visualeditor&title=Special:RecentChanges&hidecategorization=1&hideWikibase=1&hidelog=1&hidepageedits=1   Wikimedia\Rdbms\DBQueryError from line 1145 of /srv/mediawiki/php-1.30.0-wmf.5/includes/libs/rdbms/database/Database.php: A database query error has occurred. Did you forget to run your application's database schema updater after upgrading? 
Query: SELECT  rc_id,rc_timestamp,rc_user,rc_user_text,rc_namespace,rc_title,rc_comment,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,wl_user,wl_notificationtimestamp,page_latest,(SELECT  GROUP_CONCAT(ct_tag SEPARATOR ',')  FROM `change_tag`    WHERE ct_rc_id=rc_id  ) AS `ts_tags`,fp_stable,fp_pending_since,ores_damaging_cls.oresc_probability AS `ores_damaging_score`,ores_goodfaith_cls.oresc_probability AS `ores_goodfaith_score`  FROM `recentchanges` LEFT JOIN `watchlist` ON (wl_user = '26209855' AND (wl_title=rc_title) AND (wl_namespace=rc_namespace)) LEFT JOIN `page` ON ((rc_cur_id=page_id)) INNER JOIN `change_tag` ON ((ct_rc_id=rc_id)) LEFT JOIN `flaggedpages` ON ((fp_page_id = rc_cur_id)) LEFT JOIN `ores_model` `ores_damaging_mdl` ON (ores_damaging_mdl.oresm_is_current = '1' AND ores_damaging_mdl.oresm_name = 'damaging') LEFT JOIN `ores_classification` `ores_damaging_cls` ON ((ores_damaging_cls.oresc_model = ores_damaging_mdl.oresm_id) AND (rc_this_oldid = ores_damaging_cls.oresc_rev) AND ores_damaging_cls.oresc_class = '1') LEFT JOIN `ores_model` `ores_goodfaith_mdl` ON (ores_goodfaith_mdl.oresm_is_current = '1' AND ores_goodfaith_mdl.oresm_name = 'goodfaith') LEFT JOIN `ores_classification` `ores_goodfaith_cls` ON ((ores_goodfaith_cls.oresc_model = ores_goodfaith_mdl.oresm_id) AND (rc_this_oldid = ores_goodfaith_cls.oresc_rev) AND ores_goodfaith_cls.oresc_class = '1')   WHERE (rc_bot = 0) AND (rc_type != '0') AND (rc_type != '3') AND (rc_type != '6') AND (rc_source != 'wb') AND (rc_namespace = '1') AND (rc_timestamp >= '20170609000000') AND ct_tag = 'visualeditor' AND rc_new IN ('0','1')   ORDER BY rc_timestamp DESC LIMIT 50  
Function: SpecialRecentChanges::doMainQuery
Error: 2062 Read timeout is reached (10.64.32.25)
 {"exception_id":"WUPWEgpAIDgAAFdx4R8AAAAQ","caught_by":"mwe_handler"} 
[Exception Wikimedia\Rdbms\DBQueryError] (/srv/mediawiki/php-1.30.0-wmf.5/includes/libs/rdbms/database/Database.php:1145) A database query error has occurred. Did you forget to run your application's database schema updater after upgrading? 
Query: SELECT  rc_id,rc_timestamp,rc_user,rc_user_text,rc_namespace,rc_title,rc_comment,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,wl_user,wl_notificationtimestamp,page_latest,(SELECT  GROUP_CONCAT(ct_tag SEPARATOR ',')  FROM `change_tag`    WHERE ct_rc_id=rc_id  ) AS `ts_tags`,fp_stable,fp_pending_since,ores_damaging_cls.oresc_probability AS `ores_damaging_score`,ores_goodfaith_cls.oresc_probability AS `ores_goodfaith_score`  FROM `recentchanges` LEFT JOIN `watchlist` ON (wl_user = '26209855' AND (wl_title=rc_title) AND (wl_namespace=rc_namespace)) LEFT JOIN `page` ON ((rc_cur_id=page_id)) INNER JOIN `change_tag` ON ((ct_rc_id=rc_id)) LEFT JOIN `flaggedpages` ON ((fp_page_id = rc_cur_id)) LEFT JOIN `ores_model` `ores_damaging_mdl` ON (ores_damaging_mdl.oresm_is_current = '1' AND ores_damaging_mdl.oresm_name = 'damaging') LEFT JOIN `ores_classification` `ores_damaging_cls` ON ((ores_damaging_cls.oresc_model = ores_damaging_mdl.oresm_id) AND (rc_this_oldid = ores_damaging_cls.oresc_rev) AND ores_damaging_cls.oresc_class = '1') LEFT JOIN `ores_model` `ores_goodfaith_mdl` ON (ores_goodfaith_mdl.oresm_is_current = '1' AND ores_goodfaith_mdl.oresm_name = 'goodfaith') LEFT JOIN `ores_classification` `ores_goodfaith_cls` ON ((ores_goodfaith_cls.oresc_model = ores_goodfaith_mdl.oresm_id) AND (rc_this_oldid = ores_goodfaith_cls.oresc_rev) AND ores_goodfaith_cls.oresc_class = '1')   WHERE (rc_bot = 0) AND (rc_type != '0') AND (rc_type != '3') AND (rc_type != '6') AND (rc_source != 'wb') AND (rc_namespace = '1') AND (rc_timestamp >= '20170609000000') AND ct_tag = 'visualeditor' AND rc_new IN ('0','1')   ORDER BY rc_timestamp DESC LIMIT 50  
Function: SpecialRecentChanges::doMainQuery
Error: 2062 Read timeout is reached (10.64.32.25)

  #0 /srv/mediawiki/php-1.30.0-wmf.5/includes/libs/rdbms/database/Database.php(975): Wikimedia\Rdbms\Database->reportQueryError(string, integer, string, string, boolean)
  #1 /srv/mediawiki/php-1.30.0-wmf.5/includes/libs/rdbms/database/Database.php(1339): Wikimedia\Rdbms\Database->query(string, string)
  #2 /srv/mediawiki/php-1.30.0-wmf.5/includes/specials/SpecialRecentchanges.php(403): Wikimedia\Rdbms\Database->select(array, array, array, string, array, array)
  #3 /srv/mediawiki/php-1.30.0-wmf.5/includes/specialpage/ChangesListSpecialPage.php(584): SpecialRecentChanges->doMainQuery(array, array, array, array, array, FormOptions)
  #4 /srv/mediawiki/php-1.30.0-wmf.5/includes/specialpage/ChangesListSpecialPage.php(520): ChangesListSpecialPage->getRows()
  #5 /srv/mediawiki/php-1.30.0-wmf.5/includes/specials/SpecialRecentchanges.php(166): ChangesListSpecialPage->execute(NULL)
  #6 /srv/mediawiki/php-1.30.0-wmf.5/includes/specialpage/SpecialPage.php(522): SpecialRecentChanges->execute(NULL)
  #7 /srv/mediawiki/php-1.30.0-wmf.5/includes/specialpage/SpecialPageFactory.php(579): SpecialPage->run(NULL)
  #8 /srv/mediawiki/php-1.30.0-wmf.5/includes/MediaWiki.php(287): SpecialPageFactory::executePath(Title, RequestContext)
  #9 /srv/mediawiki/php-1.30.0-wmf.5/includes/MediaWiki.php(862): MediaWiki->performRequest()
  #10 /srv/mediawiki/php-1.30.0-wmf.5/includes/MediaWiki.php(523): MediaWiki->main()
  #11 /srv/mediawiki/php-1.30.0-wmf.5/index.php(43): MediaWiki->run()
  #12 /srv/mediawiki/w/index.php(3): include(string)
  #13 {main}

Related Objects
Search...

Status	Subtype	Assigned	Task
Resolved		• DannyH	T171977 Annual Plan 2017-2018, Audiences 5: Increase current editor retention and engagement
Resolved		• DannyH	T171981 Annual Plan 2017-2018, Audiences 5, Goal 2: Give better ways to monitor contributions
Resolved		• jmatazzoni	T157642 Graduate New Filters UX out of beta on Recent Changes on ALL wikis
Resolved		• jmatazzoni	T163757 ORES on en.wiki chokes on "V. likely good faith" + "Likely have problems"
Declined		None	T164796 Very long search times on RC Page for "Very likely good faith" + "Likely have problems" (on en.wiki only?)
Open		None	T168096 Special:RecentChanges with complex query (rc_namespace = 1 AND ct_tag = 'visualeditor') slow due to using wrong index
Duplicate	PRODUCTION ERROR	None	T177026 [1.31.0-wmf.1] RC page - Fatal exception of type "Wikimedia\Rdbms\DBQueryTimeoutError" for a saved filter

Event Timeline

• Mattflaschen-WMF created this task.Jun 16 2017, 9:08 PM

Restricted Application added a project: Collaboration-Team-Triage. · View Herald TranscriptJun 16 2017, 9:08 PM

Restricted Application added a subscriber: Aklapper. · View Herald Transcript

• Mattflaschen-WMF added a parent task: T164796: Very long search times on RC Page for "Very likely good faith" + "Likely have problems" (on en.wiki only?).Jun 16 2017, 9:08 PM

• Mattflaschen-WMF added projects: MediaWiki-extensions-ORES, MediaWiki-extensions-FlaggedRevs.

Restricted Application added a project: Machine-Learning-Team. · View Herald TranscriptJun 16 2017, 9:09 PM

Restricted Application added a subscriber: TerraCodes. · View Herald Transcript

• Mattflaschen-WMF added a subscriber: Etonkovidova.Jun 16 2017, 9:09 PM

• Mattflaschen-WMF moved this task from Untriaged to Medium-Term Interest on the Collaboration-Team-Triage board.Jun 20 2017, 5:55 PM

Ladsgroup edited projects, added Machine-Learning-Team (Active Tasks); removed Machine-Learning-Team.Jun 22 2017, 2:47 PM

Ladsgroup moved this task from Parked to Monitor (long term) on the Machine-Learning-Team (Active Tasks) board.

awight mentioned this in T169429: Fatal DBQueryError "Read timeout is reached" exception when using ORES on Special:Contributions.Jul 6 2017, 4:37 AM

Clarification: this query is looking for edits tagged visualeditor in the Talk namespace, and there aren't any. Not sure what if there's anything we can do about this, because it's hard to know in software that this is an impossible combination.

Halfak edited projects, added Machine-Learning-Team; removed Machine-Learning-Team (Active Tasks).Sep 6 2017, 5:23 PM

Halfak moved this task from Unsorted to Backlog/Lift Wing on the Machine-Learning-Team board.Sep 6 2017, 5:27 PM

awight mentioned this in T176456: ORES on Watchlist causes big slowdown—especially with 'Last revision' filter turned on.Sep 27 2017, 5:53 PM

@Mattflaschen-WMF I'm sure it's in there somewhere, but can you state simply what the query is. And give a link with the parameters? Thanks.

Etonkovidova added a subtask: T177026: [1.31.0-wmf.1] RC page - Fatal exception of type "Wikimedia\Rdbms\DBQueryTimeoutError" for a saved filter.Sep 28 2017, 10:01 PM

Aklapper mentioned this in T178109: Wikimedia\Rdbms\DBQueryTimeoutError on Special:Contributions filtering by namespace.Oct 13 2017, 10:10 AM

This probably should be using the tmp_3 index (which is on production but not in mediawiki - its on (rc_namespace, rc_timestamp)) But according to the explain on production its using the rc_timestamp index. [my quick test showed 3.48 seconds when FORCE INDEX for tmp_3 vs 42.65 for query as is. Running the faster query first, so any effects of warm cache would favour the slow one]

From the explain, it appears that mariadb thinks that tmp_3 would require 594328 rows, where rc_timestamp requires only 9453 - which is clearly wrong, thus explaining why the wrong index is used.

I don't know if DBA 's can do anything here to optimize index statistics. We certainly can't force the index when its not an index in core (Maybe we should move that index to core?) Even if it was in core, there's so many variations on recentchanges query we have to be careful not to break one of the other variants of the query. Perhaps IGNORE INDEX( rc_timestamp ) would be better, but even then, mysql still tries to use tmp_2 (rc_bot, rc_timestamp) instead of the right index. IGNORE INDEX( rc_timestamp, tmp_2 ) does cause the right index to be used.

Bawolff renamed this task from Read timeout on Special:RecentChanges with complex query to Special:RecentChanges with complex query (rc_namespace = 1 AND ct_tag = 'visualeditor') slow due to using wrong index.Oct 13 2017, 5:24 PM

matej_suchanek added a project: TestMe.Feb 9 2019, 5:10 PM

Restricted Application added a project: Growth-Team. · View Herald TranscriptFeb 9 2019, 5:10 PM

Maintenance_bot moved this task from Backlog/Lift Wing to Backlog/ORES on the Machine-Learning-Team board.Jan 19 2021, 11:30 PM

MBinder_WMF added a project: Growth-Team-Filtering.Apr 15 2021, 6:56 PM

Aklapper removed a project: Collaboration-Team-Triage.May 25 2021, 9:09 PM

Umherirrender added a project: Wikimedia-Slow-DB-Query.May 8 2022, 6:47 PM