Page MenuHomePhabricator

Read timeout reached on AbuseFilterViewTestBatch
Closed, ResolvedPublicPRODUCTION ERROR

Description

Error

Request ID: AWhRaNq3zpjgITg6UGP1

message
A database query timeout has occurred. 
Query: 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,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_user,rc_user_text,NULL AS `rc_actor`  FROM `recentchanges` JOIN `comment` `comment_rc_comment` ON ((comment_rc_comment.comment_id = rc_comment_id))   WHERE ((rc_user = 'XXXXXXXX')) AND (rc_source IN ('mw.edit','mw.new')  OR (rc_source = 'mw.log' AND ((rc_log_type = 'move' AND rc_log_action = 'move') OR (rc_log_type = 'newusers' AND rc_log_action IN ('create','autocreate') ) OR (rc_log_type = 'delete' AND rc_log_action = 'delete'))))  ORDER BY rc_timestamp desc LIMIT 100  
Function: AbuseFilterViewTestBatch::doTest
Error: 2062 Read timeout is reached
trace
#0 /srv/mediawiki/php-1.33.0-wmf.12/includes/libs/rdbms/database/Database.php(1476): Wikimedia\Rdbms\Database->makeQueryException(string, integer, string, string)
#1 /srv/mediawiki/php-1.33.0-wmf.12/includes/libs/rdbms/database/Database.php(1236): Wikimedia\Rdbms\Database->reportQueryError(string, integer, string, string, boolean)
#2 /srv/mediawiki/php-1.33.0-wmf.12/includes/libs/rdbms/database/Database.php(1703): Wikimedia\Rdbms\Database->query(string, string)
#3 /srv/mediawiki/php-1.33.0-wmf.12/extensions/AbuseFilter/includes/Views/AbuseFilterViewTestBatch.php(182): Wikimedia\Rdbms\Database->select(array, array, array, string, array, array)
#4 /srv/mediawiki/php-1.33.0-wmf.12/extensions/AbuseFilter/includes/Views/AbuseFilterViewTestBatch.php(119): AbuseFilterViewTestBatch->doTest()
#5 /srv/mediawiki/php-1.33.0-wmf.12/extensions/AbuseFilter/includes/special/SpecialAbuseFilter.php(122): AbuseFilterViewTestBatch->show()
#6 /srv/mediawiki/php-1.33.0-wmf.12/includes/specialpage/SpecialPage.php(569): SpecialAbuseFilter->execute(string)
#7 /srv/mediawiki/php-1.33.0-wmf.12/includes/specialpage/SpecialPageFactory.php(558): SpecialPage->run(string)
#8 /srv/mediawiki/php-1.33.0-wmf.12/includes/MediaWiki.php(288): MediaWiki\Special\SpecialPageFactory->executePath(Title, RequestContext)
#9 /srv/mediawiki/php-1.33.0-wmf.12/includes/MediaWiki.php(862): MediaWiki->performRequest()
#10 /srv/mediawiki/php-1.33.0-wmf.12/includes/MediaWiki.php(517): MediaWiki->main()
#11 /srv/mediawiki/php-1.33.0-wmf.12/index.php(42): MediaWiki->run()
#12 /srv/mediawiki/w/index.php(3): include(string)
#13 {main}

Impact

Presumably low, seen 4 times in the last 7 days.

Notes

Running an EXPLAIN SELECT on my wiki:

+------+-------------+--------------------+--------+---------------+---------------+---------+--------------------------------------+------+-----------------------------+
|  id  | select_type |        table       |  type  | possible_keys |      key      | key_len |                ref                   | rows |            Extra            |
+------+-------------+--------------------+--------+---------------+---------------+---------+--------------------------------------+------+-----------------------------+
|    1 |    SIMPLE   |    recentchanges   |   ALL  |      NULL     |     NULL      |   NULL  |                NULL                  |  233 | Using where; Using filesort |
+------+-------------+--------------------+--------+---------------+---------------+---------+--------------------------------------+------+-----------------------------+
|    1 |    SIMPLE   | comment_rc_comment | eq_ref |    PRIMARY    |    PRIMARY    |    8    |  my_wiki.recentchanges.rc_comment_id |    1 |                             |
+------+-------------+--------------------+--------+---------------+---------------+---------+--------------------------------------+------+-----------------------------+

And the using filesort is bad...

Event Timeline

I see that the problem here is using WHERE rc_user = 'XXXXXXXX'. The field is not indexed, and thus the filesort. However, I also see that the field is deprecated in favour of rc_actor (which has an index together with timestamp), and thus this should be fixed with actor conversion. Leaving open as memo.

Of note, the same query is logged as slow on Tendril also when performed for IndexPager::buildQueryInfo (AbuseFilterExaminePager).

mmodell changed the subtype of this task from "Task" to "Production Error".Aug 28 2019, 11:07 PM