Page MenuHomePhabricator

Page creation log cannot be viewed from oldest records, Fatal: "execution time limit of 60 seconds was exceeded"
Closed, ResolvedPublic

Description

I wanted to know when page creation logging was started. I opened page creation log and pressed "oldest" link, but got an error:
[XbrskwpAICEAAE97bbIAAAAB] 2019-10-31 14:17:03: Неустранимое исключение типа «WMFTimeoutException» .
Checked 3 times.
Link: https://ru.wikipedia.org/w/index.php?title=Special:Log&dir=prev&type=create

Details

Request ID
XbrskwpAICEAAE97bbIAAAAB
Stack Trace

#0 /srv/mediawiki/php-1.35.0-wmf.3/includes/exception/MWExceptionHandler.php(200): {closure}(integer)
#1 [internal function]: MWExceptionHandler::handleError(integer, string, string, integer, array)
#2 /srv/mediawiki/php-1.35.0-wmf.3/includes/libs/rdbms/database/DatabaseMysqli.php(46): mysqli->query(string)
#3 /srv/mediawiki/php-1.35.0-wmf.3/includes/libs/rdbms/database/Database.php(1308): Wikimedia\Rdbms\DatabaseMysqli->doQuery(string)
#4 /srv/mediawiki/php-1.35.0-wmf.3/includes/libs/rdbms/database/Database.php(1226): Wikimedia\Rdbms\Database->executeQueryAttempt(string, string, boolean, string, integer)
#5 /srv/mediawiki/php-1.35.0-wmf.3/includes/libs/rdbms/database/Database.php(1162): Wikimedia\Rdbms\Database->executeQuery(string, string, integer)
#6 /srv/mediawiki/php-1.35.0-wmf.3/includes/libs/rdbms/database/Database.php(1828): Wikimedia\Rdbms\Database->query(string, string)
#7 /srv/mediawiki/php-1.35.0-wmf.3/includes/libs/rdbms/database/DBConnRef.php(68): Wikimedia\Rdbms\Database->select(array, array, array, string, array, array)
#8 /srv/mediawiki/php-1.35.0-wmf.3/includes/libs/rdbms/database/DBConnRef.php(318): Wikimedia\Rdbms\DBConnRef->__call(string, array)
#9 /srv/mediawiki/php-1.35.0-wmf.3/includes/pager/IndexPager.php(418): Wikimedia\Rdbms\DBConnRef->select(array, array, array, string, array, array)
#10 /srv/mediawiki/php-1.35.0-wmf.3/includes/pager/IndexPager.php(263): IndexPager->reallyDoQuery(string, integer, boolean)
#11 /srv/mediawiki/php-1.35.0-wmf.3/includes/logging/LogPager.php(474): IndexPager->doQuery()
#12 /srv/mediawiki/php-1.35.0-wmf.3/includes/pager/IndexPager.php(474): LogPager->doQuery()
#13 /srv/mediawiki/php-1.35.0-wmf.3/includes/specials/SpecialLog.php(244): IndexPager->getBody()
#14 /srv/mediawiki/php-1.35.0-wmf.3/includes/specials/SpecialLog.php(134): SpecialLog->show(FormOptions, array)
#15 /srv/mediawiki/php-1.35.0-wmf.3/includes/specialpage/SpecialPage.php(575): SpecialLog->execute(NULL)
#16 /srv/mediawiki/php-1.35.0-wmf.3/includes/specialpage/SpecialPageFactory.php(607): SpecialPage->run(NULL)
#17 /srv/mediawiki/php-1.35.0-wmf.3/includes/MediaWiki.php(298): MediaWiki\Special\SpecialPageFactory->executePath(Title, RequestContext)
#18 /srv/mediawiki/php-1.35.0-wmf.3/includes/MediaWiki.php(967): MediaWiki->performRequest()
#19 /srv/mediawiki/php-1.35.0-wmf.3/includes/MediaWiki.php(530): MediaWiki->main()
#20 /srv/mediawiki/php-1.35.0-wmf.3/index.php(44): MediaWiki->run()
#21 /srv/mediawiki/w/index.php(3): require(string)
#22 {main}

Related Gerrit Patches:

Event Timeline

MBH created this task.Oct 31 2019, 3:11 PM
Restricted Application added subscribers: Base, Aklapper. · View Herald TranscriptOct 31 2019, 3:11 PM
Aklapper renamed this task from Page creation log cannot be viewed from oldest records to Page creation log cannot be viewed from oldest records: "the execution time limit of 60 seconds was exceeded".Oct 31 2019, 4:53 PM
Aklapper changed the subtype of this task from "Task" to "Production Error".
Aklapper set Request ID to XbrskwpAICEAAE97bbIAAAAB.
Aklapper updated the task description. (Show Details)
Aklapper edited Stack Trace. (Show Details)
Krinkle renamed this task from Page creation log cannot be viewed from oldest records: "the execution time limit of 60 seconds was exceeded" to Page creation log cannot be viewed from oldest records, Fatal: "execution time limit of 60 seconds was exceeded".Nov 7 2019, 8:53 PM
Krinkle added a project: Core Platform Team.
Krinkle updated the task description. (Show Details)
Anomie added subscribers: Marostegui, Anomie.

The query in question here is

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,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`,actor_log_user.actor_user AS `log_user`,actor_log_user.actor_name AS `log_user_text`,log_actor,(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 `comment` `comment_log_comment` ON ((comment_log_comment.comment_id = log_comment_id)) JOIN `actor` `actor_log_user` ON ((actor_log_user.actor_id = log_actor)) LEFT JOIN `user` ON ((user_id=actor_log_user.actor_user))   WHERE (log_type NOT IN ('titleblacklist','abusefilterprivatedetails','oath','suppress')) AND log_type = 'create'  ORDER BY log_timestamp LIMIT 51

On at least one ruwiki host, I find this bad query plan using the times index:

wikiadmin@10.64.16.34(ruwiki)> 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,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`,actor_log_user.actor_user AS `log_user`,actor_log_user.actor_name AS `log_user_text`,log_actor,(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 `comment` `comment_log_comment` ON ((comment_log_comment.comment_id = log_comment_id)) JOIN `actor` `actor_log_user` ON ((actor_log_user.actor_id = log_actor)) LEFT JOIN `user` ON ((user_id=actor_log_user.actor_user))   WHERE (log_type NOT IN ('titleblacklist','abusefilterprivatedetails','oath','suppress')) AND log_type = 'create'  ORDER BY log_timestamp LIMIT 51;
+------+--------------------+---------------------+--------+----------------------------------------------------------------------+-----------------------+---------+----------------------------------+------+-------------+
| id   | select_type        | table               | type   | possible_keys                                                        | key                   | key_len | ref                              | rows | Extra       |
+------+--------------------+---------------------+--------+----------------------------------------------------------------------+-----------------------+---------+----------------------------------+------+-------------+
|    1 | PRIMARY            | logging             | index  | type_time,type_action,actor_time,log_actor_type_time,log_type_action | times                 | 16      | NULL                             | 3018 | Using where |
|    1 | PRIMARY            | comment_log_comment | eq_ref | PRIMARY                                                              | PRIMARY               | 8       | ruwiki.logging.log_comment_id    |    1 |             |
|    1 | PRIMARY            | actor_log_user      | eq_ref | PRIMARY                                                              | PRIMARY               | 8       | ruwiki.logging.log_actor         |    1 |             |
|    1 | PRIMARY            | user                | eq_ref | PRIMARY                                                              | PRIMARY               | 4       | ruwiki.actor_log_user.actor_user |    1 | Using where |
|    2 | DEPENDENT SUBQUERY | change_tag          | ref    | change_tag_log_tag_id,change_tag_tag_id_id                           | change_tag_log_tag_id | 5       | ruwiki.logging.log_id            |   17 | Using index |
|    2 | DEPENDENT SUBQUERY | change_tag_def      | eq_ref | PRIMARY                                                              | PRIMARY               | 4       | ruwiki.change_tag.ct_tag_id      |    1 |             |
+------+--------------------+---------------------+--------+----------------------------------------------------------------------+-----------------------+---------+----------------------------------+------+-------------+

The better plan would be more like this, using the type_time index.

wikiadmin@10.64.16.11(ruwiki)> 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,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`,actor_log_user.actor_user AS `log_user`,actor_log_user.actor_name AS `log_user_text`,log_actor,(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 `comment` `comment_log_comment` ON ((comment_log_comment.comment_id = log_comment_id)) JOIN `actor` `actor_log_user` ON ((actor_log_user.actor_id = log_actor)) LEFT JOIN `user` ON ((user_id=actor_log_user.actor_user))   WHERE (log_type NOT IN ('titleblacklist','abusefilterprivatedetails','oath','suppress')) AND log_type = 'create'  ORDER BY log_timestamp LIMIT 51;
+------+--------------------+---------------------+--------+----------------------------------------------------------------------+-----------------------+---------+----------------------------------+--------+------------------------------------+
| id   | select_type        | table               | type   | possible_keys                                                        | key                   | key_len | ref                              | rows   | Extra                              |
+------+--------------------+---------------------+--------+----------------------------------------------------------------------+-----------------------+---------+----------------------------------+--------+------------------------------------+
|    1 | PRIMARY            | logging             | ref    | type_time,type_action,actor_time,log_actor_type_time,log_type_action | type_time             | 34      | const                            | 938326 | Using index condition; Using where |
|    1 | PRIMARY            | comment_log_comment | eq_ref | PRIMARY                                                              | PRIMARY               | 8       | ruwiki.logging.log_comment_id    |      1 |                                    |
|    1 | PRIMARY            | actor_log_user      | eq_ref | PRIMARY                                                              | PRIMARY               | 8       | ruwiki.logging.log_actor         |      1 |                                    |
|    1 | PRIMARY            | user                | eq_ref | PRIMARY                                                              | PRIMARY               | 4       | ruwiki.actor_log_user.actor_user |      1 | Using where                        |
|    2 | DEPENDENT SUBQUERY | change_tag          | ref    | change_tag_log_tag_id,change_tag_tag_id_id                           | change_tag_log_tag_id | 5       | ruwiki.logging.log_id            |     15 | Using index                        |
|    2 | DEPENDENT SUBQUERY | change_tag_def      | eq_ref | PRIMARY                                                              | PRIMARY               | 4       | ruwiki.change_tag.ct_tag_id      |      1 |                                    |
+------+--------------------+---------------------+--------+----------------------------------------------------------------------+-----------------------+---------+----------------------------------+--------+------------------------------------+

The good plan runs in ~0.01s, versus ~130s for the bad plan.

This seems to be more or less the same thing as we had at T223151#5508503, where it was choosing times over actor_time. We could fix it the same way, by adding IGNORE INDEX (times) when the query has specific log_type in the WHERE clause. @Marostegui, do you have any better ideas for this sort of thing?

Marostegui moved this task from Triage to In progress on the DBA board.

This bad index choice also happens on enwiki from what I can see:

  • db1089 chooses times....I killed the query after 10 seconds
  • db1134 chooses type_time (0.01)

Both hosts have the same mariadb version, 10.1.39.
The enwiki hosts that run 10.1.42 do use the correct index, but it could be just a coincidence.

I have upgraded db1089 to 10.1.43 and the result is the same, so it doesn't look version related (as expected).

I could try to re-run the table stats and all that, but I am sure that won't help much as we have seen before, so I do believe this is the optimizer being silly again.
@Anomie we should probably go for the IGNORE again.

Change 550758 had a related patch set uploaded (by Anomie; owner: Anomie):
[mediawiki/core@master] LogPager: Add IGNORE INDEX to avoid another MariaDB optimizer bug

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

Change 550758 merged by jenkins-bot:
[mediawiki/core@master] LogPager: Add IGNORE INDEX to avoid another MariaDB optimizer bug

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

Anomie closed this task as Resolved.Thu, Nov 14, 3:55 PM
Anomie claimed this task.

The fix should be deployed to Wikimedia wikis with 1.35.0-wmf.8, see https://www.mediawiki.org/wiki/MediaWiki_1.35/Roadmap for a schedule.