Steps to replicate the issue (include links if applicable):
What happens?:
[59b9a689-7941-4448-88d2-65e1121502e7] 2024-11-22 18:25:34: Fatal exception of type "Wikimedia\Rdbms\DBQueryTimeoutError"
Using the query from T432191: Wikimedia\Rdbms\DBQueryTimeoutError: A database query timeout has occurred. Page: Special:Log...
SELECT log_id,log_type,log_action,log_timestamp,log_namespace,log_title,log_params,log_deleted,user_id,user_name,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)) JOIN `change_tag` `changetagdisplay` ON ((changetagdisplay.ct_log_id=log_id)) WHERE (log_type NOT IN ('spamblacklist','titleblacklist','urlshortener','abusefilter','abusefilterprivatedetails','abusefilterblockeddomainhit','abusefilter-protected-vars','oath','checkuser-temporary-account','checkuser-private-event','ipinfo','suppress')) AND changetagdisplay.ct_tag_id = 14 ORDER BY log_timestamp DESC,log_id DESC LIMIT 501SELECT log_id, log_type, log_action, log_timestamp, log_namespace, log_title, log_params, log_deleted, user_id, user_name, 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)) JOIN `change_tag` `changetagdisplay` ON ((changetagdisplay.ct_log_id=log_id)) WHERE (log_type NOT IN ( 'spamblacklist', 'titleblacklist', 'urlshortener', 'abusefilter', 'abusefilterprivatedetails', 'abusefilterblockeddomainhit', 'abusefilter-protected-vars', 'oath', 'checkuser-temporary-account', 'checkuser-private-event', 'ipinfo', 'suppress' )) AND changetagdisplay.ct_tag_id = 14 ORDER BY log_timestamp DESC, log_id DESC LIMIT 501;
changetagdisplay.ct_tag_id = 14 is probably the part of this query that makes it specific to a selected tag.
+------+--------------------+---------------------+--------+--------------------------------------------------------------------------+---------------+---------+-----------------------------------+--------+-----------------------------------------------------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +------+--------------------+---------------------+--------+--------------------------------------------------------------------------+---------------+---------+-----------------------------------+--------+-----------------------------------------------------------+ | 1 | PRIMARY | changetagdisplay | ref | ct_log_tag_id,ct_tag_id_id | ct_tag_id_id | 4 | const | 581006 | Using where; Using index; Using temporary; Using filesort | | 1 | PRIMARY | logging | eq_ref | PRIMARY,log_actor_type_time,log_type_action,log_type_time,log_actor_time | PRIMARY | 4 | enwiki.changetagdisplay.ct_log_id | 1 | Using where | | 1 | PRIMARY | logging_actor | eq_ref | PRIMARY | PRIMARY | 8 | enwiki.logging.log_actor | 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 | 7 | Using index | | 2 | DEPENDENT SUBQUERY | change_tag_def | eq_ref | PRIMARY | PRIMARY | 4 | enwiki.change_tag.ct_tag_id | 1 | | +------+--------------------+---------------------+--------+--------------------------------------------------------------------------+---------------+---------+-----------------------------------+--------+-----------------------------------------------------------+
It's going through 531,000 rows using filesort, with a 30 second limitation. Perhaps this bug crops up whenever the selected tag(s) have lots of entries. Perhaps adding an index somewhere could help.
Note that the database changed the order in which the tables are queried – the query says SELECT ... FROM `logging` ... JOIN `change_tag` `changetagdisplay`, but the EXPLAIN table shows changetagdisplay being queried first.
This can be prevented by using STRAIGHT_JOIN `change_tag` `changetagdisplay` instead:
+------+--------------------+---------------------+--------+--------------------------------------------------------------------------+---------------+---------+---------------------------------+------+-------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +------+--------------------+---------------------+--------+--------------------------------------------------------------------------+---------------+---------+---------------------------------+------+-------------+ | 1 | PRIMARY | logging | index | PRIMARY,log_actor_type_time,log_type_action,log_type_time,log_actor_time | log_times | 14 | NULL | 501 | Using where | | 1 | PRIMARY | logging_actor | eq_ref | PRIMARY | PRIMARY | 8 | enwiki.logging.log_actor | 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 | | | 1 | PRIMARY | changetagdisplay | eq_ref | ct_log_tag_id,ct_tag_id_id | ct_log_tag_id | 9 | enwiki.logging.log_id,const | 1 | Using index | | 2 | DEPENDENT SUBQUERY | change_tag | ref | ct_log_tag_id,ct_tag_id_id | ct_log_tag_id | 5 | enwiki.logging.log_id | 7 | Using index | | 2 | DEPENDENT SUBQUERY | change_tag_def | eq_ref | PRIMARY | PRIMARY | 4 | enwiki.change_tag.ct_tag_id | 1 | | +------+--------------------+---------------------+--------+--------------------------------------------------------------------------+---------------+---------+---------------------------------+------+-------------+
This avoids the filesort, and – in this case, in my testing, on Analytics replicas – makes the query faster. I remember, however, that we used to occasionally add and remove this in various queries. Which variant is faster depends on the shape of the data, and our database is not smart enough to always figure out which is better.