Page MenuHomePhabricator

Database error when filtering page log
Closed, ResolvedPublic

Description

On filtering the en:wp page move log by Tag (specifically the 'de-userfying' tag) I get the following MySQL error:

A database query error has occurred. This may indicate a bug in the software.

Function: IndexPager::buildQueryInfo (LogPager)
Error: 2013 Lost connection to MySQL server during query (10.64.32.21)

This is the precise query URL.

I am using FF 47.0b9 on Windows 10, am logged in as a non-admin user and have cleared local caches.

Event Timeline

Samtar created this task.Jun 1 2016, 8:59 AM
Restricted Application added subscribers: Zppix, Aklapper. · View Herald TranscriptJun 1 2016, 8:59 AM
Aklapper edited projects, added DBA; removed Operations.Jun 1 2016, 3:26 PM
jcrespo added a subscriber: jcrespo.Jun 1 2016, 3:39 PM

This is a horrible, horrible query to do:

SELECT log_id,log_type,log_action,log_timestamp,log_user,log_user_text,log_namespace,log_title,log_comment,log_params,log_deleted,user_id,user_name,user_editcount,(SELECT GROUP_CONCAT(ct_tag SEPARATOR ',') FROM `change_tag` WHERE ct_log_id=log_id ) AS `ts_tags` FROM `logging` LEFT JOIN `user` ON ((log_user=user_id)) WHERE (log_type NOT IN ('spamblacklist','titleblacklist','suppress')) AND log_user = 'XXXXXX' AND ((log_deleted & 4) = 0) AND (log_type != 'thanks') AND (log_type != 'tag') ORDER BY log_timestamp DESC LIMIT 51
*************************** 1. row ***************************
           id: 1
  select_type: PRIMARY
        table: change_tag
         type: ref
possible_keys: ct_log_id,change_tag_log_tag,ct_tag,change_tag_tag_id
          key: ct_tag
      key_len: 257
          ref: const
         rows: 8456
        Extra: Using where; Using index; Using temporary; Using filesort
*************************** 2. row ***************************
           id: 1
  select_type: PRIMARY
        table: logging
         type: eq_ref
possible_keys: PRIMARY,type_time
          key: PRIMARY
      key_len: 4
          ref: enwiki.change_tag.ct_log_id
         rows: 1
        Extra: Using where
*************************** 3. row ***************************
           id: 1
  select_type: PRIMARY
        table: user
         type: eq_ref
possible_keys: PRIMARY
          key: PRIMARY
      key_len: 4
          ref: enwiki.logging.log_user
         rows: 1
        Extra: 
*************************** 4. row ***************************
           id: 2
  select_type: DEPENDENT SUBQUERY
        table: change_tag
         type: ref
possible_keys: ct_log_id,change_tag_log_tag
          key: change_tag_log_tag
      key_len: 5
          ref: enwiki.logging.log_id
         rows: 1
        Extra: Using where; Using index
4 rows in set (0.11 sec)

https://logstash.wikimedia.org/#dashboard/temp/AVUMmtEd_LTxu7wlStpN

jcrespo edited projects, added Wikimedia-Rdbms; removed DBA.Jun 1 2016, 3:40 PM
matmarex added subscribers: Springle, matmarex.EditedJul 7 2016, 8:26 AM

This part looked weird to me, because we have the tag_summary table exactly to avoid GROUP_CONCAT:

SELECT GROUP_CONCAT(ct_tag SEPARATOR ',') FROM `change_tag`

But this looks to come from https://gerrit.wikimedia.org/r/#/c/95584/ (T55577) and was okayed by @Springle. That was back in 2013 though…

matmarex removed a subscriber: matmarex.Jul 7 2016, 8:27 AM
TTO added a subscriber: TTO.Feb 12 2017, 2:27 PM

This is a horrible, horrible query to do:

SELECT log_id,log_type,log_action,log_timestamp,log_user,log_user_text,log_namespace,log_title,log_comment,log_params,log_deleted,user_id,user_name,user_editcount,(SELECT GROUP_CONCAT(ct_tag SEPARATOR ',') FROM `change_tag` WHERE ct_log_id=log_id ) AS `ts_tags` FROM `logging` LEFT JOIN `user` ON ((log_user=user_id)) WHERE (log_type NOT IN ('spamblacklist','titleblacklist','suppress')) AND log_user = 'XXXXXX' AND ((log_deleted & 4) = 0) AND (log_type != 'thanks') AND (log_type != 'tag') ORDER BY log_timestamp DESC LIMIT 51

That SQL doesn't match the EXPLAIN output. There's no WHERE clause on change_tag.

The actual query being executed here is something like

SELECT /* IndexPager::buildQueryInfo (LogPager) */ log_id,log_type,log_action,log_timestamp,log_user,log_user_text,log_namespace,log_title,log_comment,log_params,log_deleted,user_id,user_name,user_editcount,(SELECT GROUP_CONCAT(ct_tag SEPARATOR ',') FROM `change_tag` WHERE ct_log_id=log_id ) AS `ts_tags` FROM `logging` LEFT JOIN `user` ON ((log_user=user_id)) INNER JOIN `change_tag` ON ((ct_log_id=log_id)) WHERE (log_type != 'suppress') AND log_type = 'move' AND ct_tag = 'de-userfying' ORDER BY log_timestamp DESC LIMIT 51

When I EXPLAIN this query on a local MW installation, the correct index on change_tag (change_tag_log_tag) is used, with no filesort.

@TTO I think explain output is likely to change when data changes, and this is probably caused by a user with logs of change tags/logs, which may not show up on your local installation. It could also change based on the DBMS version used. Normally here I copy the results from production, so they are quite accurate- if not, we would have not received an error report in the first place.

TTO added a comment.Apr 9 2018, 12:44 PM

Jaime, I think my observation related to the fact that the query you quoted didn't appear to correspond to the EXPLAIN output pasted below it. This may just be my amateurishness coming to the fore, but the first part of the EXPLAIN relates to the involvement of change_tag in the PRIMARY query, when change_tag only appears in the dependent subquery. (Or is this just a feature of how MySQL handles dependent subqueries?)

Moreover, the query you quoted has no mention of filtering on ct_tag, even though the original reporter was complaining that the query was timing out when they filtered on a specific change tag. The query also does not mention the move log, which is another feature of the original report. That suggests to me that the query you were measuring is not the same as the one that was timing out for the reporter, and might be timing out for other reasons.

Isn't this done already? I can't see any errors when I open the link. Very likely because of T185355 and T209525

Ladsgroup closed this task as Resolved.Jan 21 2019, 10:19 AM
Ladsgroup claimed this task.

I'm going to call this closed as I don't see any errors anymore. Feel free to reopen in case you disagree.

Restricted Application added a project: User-Ladsgroup. · View Herald TranscriptJan 21 2019, 10:19 AM