Page MenuHomePhabricator
Create Task
Maniphest T206042

Job cirrusSearchIncomingLinkCount failures "Read timeout is reached" from Title::getFirstRevision
Closed, ResolvedPublicPRODUCTION ERROR
Actions

Description

Error

Request ID: W7PV9ArAIFsAADtu0UIAAABX
Channel: JobExecutor

message
A database query timeout has occurred. 

Query: SELECT  rev_id,rev_page,rev_timestamp,rev_minor_edit,rev_deleted,rev_len,rev_parent_id,rev_sha1,COALESCE( comment_rev_comment.comment_text, rev_comment ) AS `rev_comment_text`,comment_rev_comment.comment_data AS `rev_comment_data`,comment_rev_comment.comment_id AS `rev_comment_cid`,rev_user,rev_user_text,NULL AS `rev_actor`,rev_text_id,rev_content_format,rev_content_model  FROM `revision` IGNORE INDEX (rev_timestamp) LEFT JOIN `revision_comment_temp` `temp_rev_comment` ON ((temp_rev_comment.revcomment_rev = rev_id)) LEFT JOIN `comment` `comment_rev_comment` ON ((comment_rev_comment.comment_id = temp_rev_comment.revcomment_comment_id))   WHERE rev_page = '#######'  ORDER BY rev_timestamp ASC, rev_id ASC LIMIT 1  

Function: Title::getFirstRevision
Error: 2062 Read timeout is reached
stacktrace
#1 /srv/mediawiki/php-1.32.0-wmf.23/includes/libs/rdbms/database/Database.php(1198): Wikimedia\Rdbms\Database->reportQueryError(string, integer, string, string, boolean)
#2 /srv/mediawiki/php-1.32.0-wmf.23/includes/libs/rdbms/database/Database.php(1655): Wikimedia\Rdbms\Database->query(string, string)
#3 /srv/mediawiki/php-1.32.0-wmf.23/includes/libs/rdbms/database/Database.php(1746): Wikimedia\Rdbms\Database->select(array, array, array, string, array, array)
#4 /srv/mediawiki/php-1.32.0-wmf.23/includes/Title.php(4429): Wikimedia\Rdbms\Database->selectRow(array, array, array, string, array, array)
#5 /srv/mediawiki/php-1.32.0-wmf.23/includes/page/WikiPage.php(705): Title->getFirstRevision()
#6 /srv/mediawiki/php-1.32.0-wmf.23/extensions/CirrusSearch/includes/Updater.php(342): WikiPage->getOldestRevision()
#7 /srv/mediawiki/php-1.32.0-wmf.23/extensions/CirrusSearch/includes/Updater.php(407): CirrusSearch\Updater::buildDocument(CirrusSearch, WikiPage, CirrusSearch\Connection, integer, integer, integer)
#8 /srv/mediawiki/php-1.32.0-wmf.23/extensions/CirrusSearch/includes/Updater.php(205): CirrusSearch\Updater->buildDocumentsForPages(array, integer)
#9 /srv/mediawiki/php-1.32.0-wmf.23/extensions/CirrusSearch/includes/Updater.php(468): CirrusSearch\Updater->updatePages(array, integer)
#10 /srv/mediawiki/php-1.32.0-wmf.23/extensions/CirrusSearch/includes/Job/IncomingLinkCount.php(36): CirrusSearch\Updater->updateLinkedArticles(array)
#11 /srv/mediawiki/php-1.32.0-wmf.23/extensions/CirrusSearch/includes/Job/Job.php(99): CirrusSearch\Job\IncomingLinkCount->doJob()
#12 /srv/mediawiki/php-1.32.0-wmf.23/extensions/EventBus/includes/JobExecutor.php(64): CirrusSearch\Job\Job->run()

Notes

Tentatively triaging as high priority because this appears to be a regression that started quite recently at a very specific point in time:

capture.png (859×2 px, 67 KB)

It started September 12 with the deployment of 1.32.0-wmf.20, it appears to be specific to CirrusSearch jobs for en.wikipedia.org

Details

SubjectRepoBranchLines +/-
Updater: Pull only the timestamp of oldest revisionmediawiki/extensions/CirrusSearchmaster+62 -1
Customize query in gerrit

Related Objects

Event Timeline

Krinkle triaged this task as High priority.Oct 2 2018, 9:31 PM
Krinkle created this task.
Restricted Application added a project: Discovery-Search. · View Herald TranscriptOct 2 2018, 9:31 PM
Restricted Application added a subscriber: Aklapper. · View Herald Transcript
Krinkle added a comment.Oct 2 2018, 9:37 PM

This affects job_type cirrusSearchLinksUpdatePrioritized as well. Identical stacktrace otherwise.

EBernhardson subscribed.EditedOct 2 2018, 10:09 PM

We started calling Revision::getFirstRevision (via WikiPage::getOldestRevision) in https://gerrit.wikimedia.org/r/#/c/mediawiki/extensions/CirrusSearch/+/433986/3/includes/Updater.php as part of T195071. Nothing should be new to this code path on the CirrusSearch side since that patch was deployed in late may.

My guess would be that either the query changed, or query planning changed. Git logs suggest the main query declaration hasn't changed much since at least 2017, although potentially joins requested from Revision::getQueryInfo() that i'm not familiar with could have changed the underlying query. A check in prod shows this is (roughly) the query issued:

SELECT rev_id, 
       rev_page, 
       rev_timestamp, 
       rev_minor_edit, 
       rev_deleted, 
       rev_len, 
       rev_parent_id, 
       rev_sha1, 
       Coalesce(comment_rev_comment.comment_text, rev_comment) AS `rev_comment_text`, 
       comment_rev_comment.comment_data                        AS  `rev_comment_data`, 
       comment_rev_comment.comment_id                          AS `rev_comment_cid`, 
       rev_user, 
       rev_user_text, 
       NULL                                                    AS `rev_actor`,
       rev_text_id, 
       rev_content_format, 
       rev_content_model 
FROM   `revision` IGNORE INDEX (rev_timestamp) 
       LEFT JOIN `revision_comment_temp` `temp_rev_comment` 
              ON (( temp_rev_comment.revcomment_rev = rev_id )) 
       LEFT JOIN `comment` `comment_rev_comment` 
              ON (( comment_rev_comment.comment_id = temp_rev_comment.revcomment_comment_id )) 
WHERE  rev_page = '15580374' 
ORDER  BY rev_timestamp ASC, 
          rev_id ASC
LIMIT  1

And an explain (from db2072, experience says this can vary):

+------+-------------+---------------------+--------+------------------------------------------------+----------------+---------+-----------------------------------------------+------+-------------+
| id   | select_type | table               | type   | possible_keys                                  | key            | key_len | ref                                           | rows | Extra       |
+------+-------------+---------------------+--------+------------------------------------------------+----------------+---------+-----------------------------------------------+------+-------------+
|    1 | SIMPLE      | revision            | ref    | page_timestamp,page_user_timestamp,rev_page_id | page_timestamp | 4       | const                                         | 4193 | Using where |
|    1 | SIMPLE      | temp_rev_comment    | ref    | PRIMARY,revcomment_rev                         | PRIMARY        | 4       | enwiki.revision.rev_id                        |    1 | Using index |
|    1 | SIMPLE      | comment_rev_comment | eq_ref | PRIMARY                                        | PRIMARY        | 8       | enwiki.temp_rev_comment.revcomment_comment_id |    1 | Using where |
+------+-------------+---------------------+--------+------------------------------------------------+----------------+---------+-----------------------------------------------+------+-------------+

The joins are overkill for the CirrusSearch use case, we only actually want rev_timestamp, but since this has a limit 1 attached i wouldn't expect the join being expensive enough to matter. The choice of the page_timestamp (rev_page, rev_timestamp) index seems correct, innodb should be doing a lookup on rev_page and then a reverse scan of rev_timestamp to fetch the first revision.

Prior experience suggests perhaps different servers are choosing different query plans. I checked all s1 servers and they all come back with the expected page_timestamp index being used.

serverindex chosen
db2048 (master)page_timestamp
db2055page_timestamp
db2062page_timestamp
db2070page_timestamp
db2071page_timestamp
db2072page_timestamp
db2085page_timestamp
db2088page_timestamp
db2092page_timestamp

Overall I'm not sure yet, although for the purposes of CirrusSearch we could probably specialize a simpler query to return only the timestamp of the first revision.

debt edited projects, added Discovery-Search (Current work); removed Discovery-Search.Oct 4 2018, 5:22 PM
gerritbot subscribed.Oct 12 2018, 1:07 AM

Change 466814 had a related patch set uploaded (by EBernhardson; owner: EBernhardson):
[mediawiki/extensions/CirrusSearch@master] Updater: Pull only the timestamp of oldest revision

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

gerritbot added a project: Patch-For-Review.Oct 12 2018, 1:07 AM
EBernhardson added a comment.Oct 12 2018, 1:09 AM

Attached patch doesn't really solve the goal of this patch, which seems to identify what happened in the sept 13 deploy to change the behaviour of a previously working query, but it does simplify the query used so we might stop seeing this error.

EBernhardson moved this task from Incoming to Needs review on the Discovery-Search (Current work) board.Oct 12 2018, 1:17 AM
gerritbot added a comment.Oct 17 2018, 1:46 AM

Change 466814 merged by jenkins-bot:
[mediawiki/extensions/CirrusSearch@master] Updater: Pull only the timestamp of oldest revision

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

ReleaseTaggerBot added a project: MW-1.33-notes (1.33.0-wmf.1; 2018-10-23).Oct 17 2018, 2:01 AM
Krinkle removed a project: Patch-For-Review.Oct 24 2018, 5:44 PM
EBernhardson added a comment.Oct 29 2018, 4:48 PM

I'm not seeing these errors generated anymore, willing to call it done.

EBernhardson moved this task from Needs review to Needs Reporting on the Discovery-Search (Current work) board.Oct 29 2018, 4:48 PM
debt closed this task as Resolved.Nov 2 2018, 10:07 PM
debt claimed this task.
Krinkle moved this task from Apr 2019 / 1.33.wmf.25+ to Resolved on the Wikimedia-production-error board.Mar 25 2019, 10:35 PM
• mmodell changed the subtype of this task from "Task" to "Production Error".Aug 28 2019, 11:08 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