Page MenuHomePhabricator

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

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}

Event Timeline

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
Restricted Application added a project: Scoring-platform-team. · View Herald TranscriptJun 16 2017, 9:09 PM
Restricted Application added a subscriber: TerraCodes. · View Herald Transcript

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.

@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.

Bawolff added a subscriber: Bawolff.EditedOct 13 2017, 5:09 PM

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
Restricted Application added a project: Growth-Team. · View Herald TranscriptFeb 9 2019, 5:10 PM