Page MenuHomePhabricator
Create Task
Maniphest T303089

Consistent fatal timeout when visiting Special:Log default view for some users
Closed, ResolvedPublicPRODUCTION ERROR
Actions

Description

When I visit https://en.wikipedia.org/wiki/Special:Log/MZMcBride I'm getting a MediaWiki internal error.

MediaWiki internal error.

Original exception: [4e8e27cb-9d12-4ecc-b5ad-98e89a464988] 2022-03-04 23:33:39: Fatal exception of type "Wikimedia\Rdbms\DBQueryError"

Exception caught inside exception handler.

Set $wgShowExceptionDetails = true; at the bottom of LocalSettings.php to show detailed debugging information.

This is while logged in.

Bryan D. says the error is "Query execution was interrupted (max_statement_time exceeded)". Lego points out that in addition to timing out, we're not serving the standard error page.

2022-03-04 23:39:40 [96eccdad-9bd1-4ea2-a1bc-771ac76f90a7] mw1411 enwiki 1.38.0-wmf.24 exception ERROR: [96eccdad-9bd1-4ea2-a1bc-771ac76f90a7] /wiki/Special:Log/MZMcBride   Wikimedia\Rdbms\DBQueryError: Error 1969: Query execution was interrupted (max_statement_time exceeded) (db1134)
Function: IndexPager::buildQueryInfo (LogPager)
Query: SET STATEMENT max_statement_time=30 FOR SELECT  /*! STRAIGHT_JOIN */ log_id,log_type,log_action,log_timestamp,log_namespace,log_title,log_params,log_deleted,user_id,user_name,user_editcount,log_actor,logging_actor.actor_user AS `log_user`,logging_actor.actor_name AS `log_user_text`,comment_log_comment.comment_text AS `log_comment_text`,comment_log_comment.comment_data AS `log_comment_data`,comment_log_comment.comment_id AS `log_comment_cid`,(SELECT  GROUP_CONCAT(ctd_name SEPARATOR ',')  FROM `change_tag` JOIN `change_tag_def` ON ((ct_tag_id=ctd_id))   WHERE ct_log_id=log_id  ) AS `ts_tags`  FROM `logging` JOIN `actor` `logging_actor` ON ((actor_id=log_actor)) LEFT JOIN `user` ON ((user_id=logging_actor.actor_user)) JOIN `comment` `comment_log_comment` ON ((comment_log_comment.comment_id = log_comment_id))   WHERE (log_type NOT IN ('spamblacklist','titleblacklist','urlshortener','abusefilter','abusefilterprivatedetails','oath','suppress')) AND (log_type != 'review') AND (log_type != 'thanks') AND (log_type != 'patrol') AND (log_type != 'tag') AND log_actor = 24276 AND ((log_deleted & 4) = 0)  ORDER BY log_timestamp DESC LIMIT 51  
 {"exception_url":"/wiki/Special:Log/MZMcBride","reqId":"96eccdad-9bd1-4ea2-a1bc-771ac76f90a7","caught_by":"entrypoint"} 
[Exception Wikimedia\Rdbms\DBQueryError] (/srv/mediawiki/php-1.38.0-wmf.24/includes/libs/rdbms/database/Database.php:1655) Error 1969: Query execution was interrupted (max_statement_time exceeded) (db1134)
Function: IndexPager::buildQueryInfo (LogPager)
Query: SET STATEMENT max_statement_time=30 FOR SELECT  /*! STRAIGHT_JOIN */ log_id,log_type,log_action,log_timestamp,log_namespace,log_title,log_params,log_deleted,user_id,user_name,user_editcount,log_actor,logging_actor.actor_user AS `log_user`,logging_actor.actor_name AS `log_user_text`,comment_log_comment.comment_text AS `log_comment_text`,comment_log_comment.comment_data AS `log_comment_data`,comment_log_comment.comment_id AS `log_comment_cid`,(SELECT  GROUP_CONCAT(ctd_name SEPARATOR ',')  FROM `change_tag` JOIN `change_tag_def` ON ((ct_tag_id=ctd_id))   WHERE ct_log_id=log_id  ) AS `ts_tags`  FROM `logging` JOIN `actor` `logging_actor` ON ((actor_id=log_actor)) LEFT JOIN `user` ON ((user_id=logging_actor.actor_user)) JOIN `comment` `comment_log_comment` ON ((comment_log_comment.comment_id = log_comment_id))   WHERE (log_type NOT IN ('spamblacklist','titleblacklist','urlshortener','abusefilter','abusefilterprivatedetails','oath','suppress')) AND (log_type != 'review') AND (log_type != 'thanks') AND (log_type != 'patrol') AND (log_type != 'tag') AND log_actor = 24276 AND ((log_deleted & 4) = 0)  ORDER BY log_timestamp DESC LIMIT 51  

  #0 /srv/mediawiki/php-1.38.0-wmf.24/includes/libs/rdbms/database/Database.php(1639): Wikimedia\Rdbms\Database->getQueryException(string, integer, string, string)
  #1 /srv/mediawiki/php-1.38.0-wmf.24/includes/libs/rdbms/database/Database.php(1613): Wikimedia\Rdbms\Database->getQueryExceptionAndLog(string, integer, string, string)
  #2 /srv/mediawiki/php-1.38.0-wmf.24/includes/libs/rdbms/database/Database.php(1207): Wikimedia\Rdbms\Database->reportQueryError(string, integer, string, string, boolean)
  #3 /srv/mediawiki/php-1.38.0-wmf.24/includes/libs/rdbms/database/Database.php(1859): Wikimedia\Rdbms\Database->query(string, string, integer)
  #4 /srv/mediawiki/php-1.38.0-wmf.24/includes/libs/rdbms/database/DBConnRef.php(69): Wikimedia\Rdbms\Database->select(array, array, array, string, array, array)
  #5 /srv/mediawiki/php-1.38.0-wmf.24/includes/libs/rdbms/database/DBConnRef.php(319): Wikimedia\Rdbms\DBConnRef->__call(string, array)
  #6 /srv/mediawiki/php-1.38.0-wmf.24/includes/pager/IndexPager.php(459): Wikimedia\Rdbms\DBConnRef->select(array, array, array, string, array, array)
  #7 /srv/mediawiki/php-1.38.0-wmf.24/includes/pager/IndexPager.php(283): IndexPager->reallyDoQuery(string, integer, boolean)
  #8 /srv/mediawiki/php-1.38.0-wmf.24/includes/logging/LogPager.php(489): IndexPager->doQuery()
  #9 /srv/mediawiki/php-1.38.0-wmf.24/includes/pager/IndexPager.php(611): LogPager->doQuery()
  #10 /srv/mediawiki/php-1.38.0-wmf.24/includes/specials/SpecialLog.php(282): IndexPager->getBody()
  #11 /srv/mediawiki/php-1.38.0-wmf.24/includes/specials/SpecialLog.php(163): SpecialLog->show(FormOptions, array)
  #12 /srv/mediawiki/php-1.38.0-wmf.24/includes/specialpage/SpecialPage.php(671): SpecialLog->execute(string)
  #13 /srv/mediawiki/php-1.38.0-wmf.24/includes/specialpage/SpecialPageFactory.php(1378): SpecialPage->run(string)
  #14 /srv/mediawiki/php-1.38.0-wmf.24/includes/MediaWiki.php(315): MediaWiki\SpecialPage\SpecialPageFactory->executePath(string, RequestContext)
  #15 /srv/mediawiki/php-1.38.0-wmf.24/includes/MediaWiki.php(910): MediaWiki->performRequest()
  #16 /srv/mediawiki/php-1.38.0-wmf.24/includes/MediaWiki.php(564): MediaWiki->main()
  #17 /srv/mediawiki/php-1.38.0-wmf.24/index.php(53): MediaWiki->run()
  #18 /srv/mediawiki/php-1.38.0-wmf.24/index.php(46): wfIndexMain()
  #19 /srv/mediawiki/w/index.php(3): require(string)
  #20 {main}

Details

SubjectRepoBranchLines +/-
LogPager: Merge filter of log type into single NOT IN() clausemediawiki/coremaster+33 -40
logging: Add index hint when asking for a specific usermediawiki/corewmf/1.39.0-wmf.12+10 -0
logging: Add index hint when asking for a specific usermediawiki/corewmf/1.39.0-wmf.13+10 -0
logging: Add index hint when asking for a specific usermediawiki/coremaster+10 -0
Customize query in gerrit

Related Objects

Event Timeline

• MZMcBride created this task.Mar 4 2022, 11:38 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptMar 4 2022, 11:38 PM
Peachey88 added a project: MediaWiki-Special-pages.Mar 4 2022, 11:40 PM
Reedy changed the subtype of this task from "Bug Report" to "Production Error".Mar 4 2022, 11:41 PM
Reedy updated the task description. (Show Details)
Reedy added a project: Wikimedia-production-error.
TheresNoTime awarded a token.Mar 4 2022, 11:51 PM
• MZMcBride added a comment.Mar 5 2022, 1:38 AM

Possibly a relative of T303010: Query execution timeout for certain Special:Contributions queries.

Zabe subscribed.Mar 5 2022, 10:41 AM
Peachey88 subscribed.Mar 12 2022, 4:23 AM
Krinkle renamed this task from "MediaWiki internal error" when visiting https://en.wikipedia.org/wiki/Special:Log/MZMcBride to Consistent fatal timeout when visiting Special:Log default view for some users.Mar 14 2022, 4:39 PM
Krinkle edited projects, added MediaWiki-Logevents; removed MediaWiki-Special-pages.
Krinkle triaged this task as High priority.Mar 14 2022, 4:42 PM
Krinkle subscribed.

Some importants aspect to this:

  • It happens consistently for this URL.
  • It happens with the default settings, so simply clicking on "View logs" from the user page, contributions page, or elsewhere will trigger this.
  • It makes the logs inaccessible to most people. This is not a "power user" case of picking settings that perform badly. The logs simply can't be interacted with.
Krinkle mentioned this in T303010: Query execution timeout for certain Special:Contributions queries.Mar 14 2022, 4:48 PM
Krinkle moved this task from Untriaged to Mar 2022 on the Wikimedia-production-error board.
• Quiddity subscribed.Mar 16 2022, 7:22 PM

In case another example helps:
I just got the same thing when trying to apply the Twinkle tag to Special:Log/delete.
Testing other tags...
The tag moved with FileImporter works properly (and also has thousands of results),
The tag Huggle has very slow results (it only has 18 entries, all from 2015).

With twinkle, the error is:

MediaWiki internal error.

Original exception: [863a3b40-5d69-47f2-b2c6-46518612f243] 2022-03-16 19:15:21: Fatal exception of type "Wikimedia\Rdbms\DBQueryError"

Exception caught inside exception handler.

Set $wgShowExceptionDetails = true; at the bottom of LocalSettings.php to show detailed debugging information.
• MZMcBride added a comment.Mar 30 2022, 5:28 AM

It seems like the regular error page is being rendered now, at least:

Screen Shot 2022-03-29 at 10.21.28 PM.png (2×3 px, 865 KB)

Func subscribed.Apr 6 2022, 2:39 PM

With all filters disabled (https://en.wikipedia.org/wiki/Special:Log/MZMcBride?wpfilters%5B%5D=review&wpfilters%5B%5D=thanks&wpfilters%5B%5D=patrol&wpfilters%5B%5D=tag&wpfilters%5B%5D=newusers), this query is way faster.

gerritbot added a comment.Apr 6 2022, 2:46 PM

Change 777821 had a related patch set uploaded (by Func; author: Func):

[mediawiki/core@master] LogPager: Merge filter of log type into single NOT IN() clause

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

gerritbot added a project: Patch-For-Review.Apr 6 2022, 2:46 PM
Ladsgroup subscribed.Apr 9 2022, 5:03 PM

While that patch would make the query look nicer but the optimizer parses the query to a tree so it really doesn't make a difference in performance. Compare:

wikiadmin@10.64.16.186(enwiki)> explain SELECT  /*! STRAIGHT_JOIN */ log_id,log_type,log_action,log_timestamp,log_namespace,log_title,log_params,log_deleted,user_id,user_name,user_editcount,log_actor,logging_actor.actor_user AS `log_user`,logging_actor.actor_name AS `log_user_text`,comment_log_comment.comment_text AS `log_comment_text`,comment_log_comment.comment_data AS `log_comment_data`,comment_log_comment.comment_id AS `log_comment_cid`,(SELECT  GROUP_CONCAT(ctd_name SEPARATOR ',')  FROM `change_tag` JOIN `change_tag_def` ON ((ct_tag_id=ctd_id))   WHERE ct_log_id=log_id  ) AS `ts_tags`  FROM `logging` JOIN `actor` `logging_actor` ON ((actor_id=log_actor)) LEFT JOIN `user` ON ((user_id=logging_actor.actor_user)) JOIN `comment` `comment_log_comment` ON ((comment_log_comment.comment_id = log_comment_id))   WHERE (log_type NOT IN ('spamblacklist','titleblacklist','urlshortener','abusefilter','abusefilterprivatedetails','oath','suppress')) AND (log_type != 'review') AND (log_type != 'thanks') AND (log_type != 'patrol') AND (log_type != 'tag') AND log_actor = 24276 AND ((log_deleted & 4) = 0)  ORDER BY log_timestamp DESC LIMIT 51 ;
+------+--------------------+---------------------+--------+------------------------------------------------------------------+---------------+---------+---------------------------------+------+-------------+
| id   | select_type        | table               | type   | possible_keys                                                    | key           | key_len | ref                             | rows | Extra       |
+------+--------------------+---------------------+--------+------------------------------------------------------------------+---------------+---------+---------------------------------+------+-------------+
|    1 | PRIMARY            | logging             | index  | log_actor_type_time,log_type_action,log_type_time,log_actor_time | log_times     | 16      | NULL                            | 3131 | Using where |
|    1 | PRIMARY            | logging_actor       | const  | PRIMARY                                                          | PRIMARY       | 8       | const                           | 1    |             |
|    1 | PRIMARY            | user                | eq_ref | PRIMARY                                                          | PRIMARY       | 4       | enwiki.logging_actor.actor_user | 1    | Using where |
|    1 | PRIMARY            | comment_log_comment | eq_ref | PRIMARY                                                          | PRIMARY       | 8       | enwiki.logging.log_comment_id   | 1    |             |
|    2 | DEPENDENT SUBQUERY | change_tag          | ref    | ct_log_tag_id,ct_tag_id_id                                       | ct_log_tag_id | 5       | enwiki.logging.log_id           | 8    | Using index |
|    2 | DEPENDENT SUBQUERY | change_tag_def      | eq_ref | PRIMARY                                                          | PRIMARY       | 4       | enwiki.change_tag.ct_tag_id     | 1    |             |
+------+--------------------+---------------------+--------+------------------------------------------------------------------+---------------+---------+---------------------------------+------+-------------+
6 rows in set (0.026 sec)

wikiadmin@10.64.16.186(enwiki)> explain SELECT  /*! STRAIGHT_JOIN */ log_id,log_type,log_action,log_timestamp,log_namespace,log_title,log_params,log_deleted,user_id,user_name,user_editcount,log_actor,logging_actor.actor_user AS `log_user`,logging_actor.actor_name AS `log_user_text`,comment_log_comment.comment_text AS `log_comment_text`,comment_log_comment.comment_data AS `log_comment_data`,comment_log_comment.comment_id AS `log_comment_cid`,(SELECT  GROUP_CONCAT(ctd_name SEPARATOR ',')  FROM `change_tag` JOIN `change_tag_def` ON ((ct_tag_id=ctd_id))   WHERE ct_log_id=log_id  ) AS `ts_tags`  FROM `logging` JOIN `actor` `logging_actor` ON ((actor_id=log_actor)) LEFT JOIN `user` ON ((user_id=logging_actor.actor_user)) JOIN `comment` `comment_log_comment` ON ((comment_log_comment.comment_id = log_comment_id))   WHERE (log_type NOT IN ('spamblacklist','titleblacklist','urlshortener','abusefilter','abusefilterprivatedetails','oath','suppress', 'review', 'thanks', 'patrol', 'tag')) AND log_actor = 24276 AND ((log_deleted & 4) = 0)  ORDER BY log_timestamp DESC LIMIT 51 ;
+------+--------------------+---------------------+--------+------------------------------------------------------------------+---------------+---------+---------------------------------+------+-------------+
| id   | select_type        | table               | type   | possible_keys                                                    | key           | key_len | ref                             | rows | Extra       |
+------+--------------------+---------------------+--------+------------------------------------------------------------------+---------------+---------+---------------------------------+------+-------------+
|    1 | PRIMARY            | logging             | index  | log_actor_type_time,log_type_action,log_type_time,log_actor_time | log_times     | 16      | NULL                            | 3131 | Using where |
|    1 | PRIMARY            | logging_actor       | const  | PRIMARY                                                          | PRIMARY       | 8       | const                           | 1    |             |
|    1 | PRIMARY            | user                | eq_ref | PRIMARY                                                          | PRIMARY       | 4       | enwiki.logging_actor.actor_user | 1    | Using where |
|    1 | PRIMARY            | comment_log_comment | eq_ref | PRIMARY                                                          | PRIMARY       | 8       | enwiki.logging.log_comment_id   | 1    |             |
|    2 | DEPENDENT SUBQUERY | change_tag          | ref    | ct_log_tag_id,ct_tag_id_id                                       | ct_log_tag_id | 5       | enwiki.logging.log_id           | 8    | Using index |
|    2 | DEPENDENT SUBQUERY | change_tag_def      | eq_ref | PRIMARY                                                          | PRIMARY       | 4       | enwiki.change_tag.ct_tag_id     | 1    |             |
+------+--------------------+---------------------+--------+------------------------------------------------------------------+---------------+---------+---------------------------------+------+-------------+
6 rows in set (0.003 sec)

The problem is that logging table in enwiki seems to have bad statistics of cardinality and distribution of the indexes and as result picking the wrong index sometimes, It is being worked on.

Umherirrender subscribed.Apr 9 2022, 5:40 PM

Existing index:

INDEX log_actor_time (log_actor, log_timestamp),
INDEX log_times (log_timestamp),
INDEX log_actor_type_time (log_actor, log_type, log_timestamp),

log_times is the worse case (except full scan), because for the actor in the where condition there is an extra index log_actor_time (which shows up in my local explain), even log_actor_type_time could be a better index, but the NOT conditions are bad for index usage. It could be better to make a positive list instead of the negative list (https://gerrit.wikimedia.org/r/c/mediawiki/core/+/258413).

When cardinality are wrong, that sounds like a DBA has to run something like ANALYZE TABLE and nothing to fix in code

Krinkle added a project: Wikimedia-Slow-DB-Query.Apr 9 2022, 8:26 PM
Ladsgroup closed this task as Resolved.Apr 18 2022, 2:05 PM
Ladsgroup assigned this task to Marostegui.

Fixed now. T304626

Umherirrender mentioned this in T306584: Commons Action API DB queries for logevents timeout (internal_api_error_DBQueryTimeoutError).Apr 21 2022, 9:56 AM
Peachey88 mentioned this in T307295: Bot contributions page in Catalan wikipedia not displayed.May 1 2022, 12:24 PM
Umherirrender merged a task: T298010: Querying ProcseeBot's user logs results in internal_api_error_DBQueryError.May 1 2022, 2:12 PM
Umherirrender added subscribers: SD0001, Wellverywell, thcipriani.
Paucabot subscribed.May 1 2022, 8:30 PM
Malarz_pl subscribed.May 2 2022, 11:40 AM
Midleading subscribed.May 22 2022, 11:32 AM

Not resolved.
See https://commons.wikimedia.org/wiki/Special:Log/Daphne_Lantier

Midleading reopened this task as Open.May 22 2022, 11:33 AM
gerritbot added a comment.May 24 2022, 9:43 AM

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

[mediawiki/core@master] logging: Add index hint when asking for a specific user

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

Ladsgroup claimed this task.May 24 2022, 9:43 AM
Ladsgroup added a project: DBA.
Ladsgroup added a subscriber: Marostegui.
gerritbot added a comment.May 24 2022, 10:29 PM

Change 798505 merged by jenkins-bot:

[mediawiki/core@master] logging: Add index hint when asking for a specific user

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

ReleaseTaggerBot added a project: MW-1.39-notes (1.39.0-wmf.14; 2022-05-30).May 24 2022, 11:00 PM
gerritbot added a comment.May 25 2022, 7:47 AM

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

[mediawiki/core@wmf/1.39.0-wmf.13] logging: Add index hint when asking for a specific user

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

gerritbot added a comment.May 25 2022, 7:48 AM

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

[mediawiki/core@wmf/1.39.0-wmf.12] logging: Add index hint when asking for a specific user

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

gerritbot added a comment.May 25 2022, 9:40 AM

Change 798814 merged by jenkins-bot:

[mediawiki/core@wmf/1.39.0-wmf.13] logging: Add index hint when asking for a specific user

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

Stashbot added a comment.May 25 2022, 9:43 AM

Mentioned in SAL (#wikimedia-operations) [2022-05-25T09:43:16Z] <ladsgroup@deploy1002> Synchronized php-1.39.0-wmf.13/includes/logging/LogPager.php: Backport: [[gerrit:798814|logging: Add index hint when asking for a specific user (T303089)]] (duration: 00m 49s)

ReleaseTaggerBot edited projects, added MW-1.39-notes (1.39.0-wmf.13; 2022-05-23); removed MW-1.39-notes (1.39.0-wmf.14; 2022-05-30).May 25 2022, 10:00 AM
gerritbot added a comment.May 25 2022, 10:02 AM

Change 798815 merged by jenkins-bot:

[mediawiki/core@wmf/1.39.0-wmf.12] logging: Add index hint when asking for a specific user

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

Stashbot added a comment.May 25 2022, 10:08 AM

Mentioned in SAL (#wikimedia-operations) [2022-05-25T10:08:06Z] <ladsgroup@deploy1002> Synchronized php-1.39.0-wmf.12/includes/logging/LogPager.php: Backport: [[gerrit:798815|logging: Add index hint when asking for a specific user (T303089)]] (duration: 00m 52s)

Ladsgroup closed this task as Resolved.May 25 2022, 10:09 AM
ReleaseTaggerBot edited projects, added MW-1.39-notes (1.39.0-wmf.12; 2022-05-16); removed MW-1.39-notes (1.39.0-wmf.13; 2022-05-23).May 25 2022, 11:00 AM
matej_suchanek mentioned this in T325062: Database error when trying to view user logs of user with many log events.Dec 15 2022, 6:00 PM
TheresNoTime mentioned this in T345145: DBQueryTimeoutError for QBA-bot’s logs in Russian Wikipedia.Aug 29 2023, 12:25 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 · Credits