Page MenuHomePhabricator

Slow query on 10.4: SpecialRecentChanges::doMainQuery
Closed, ResolvedPublic

Description

I have noticed the following slow query on 10.4 (around 12 seconds runtime):
{P10509}

That query doesn't seem slow on 10.1

After optimizing recentchanges to made sure we had the latest stats.
The explain shows as follows:

+------+--------------------+--------------------+--------+----------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+---------+-----------------------------------------------------------------------+---------+-------------+
| id   | select_type        | table              | type   | possible_keys                                                                                                                                | key                   | key_len | ref                                                                   | rows    | Extra       |
+------+--------------------+--------------------+--------+----------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+---------+-----------------------------------------------------------------------+---------+-------------+
|    1 | PRIMARY            | recentchanges      | ref    | rc_timestamp,new_name_timestamp,tmp_2,tmp_3,rc_name_type_patrolled_timestamp,rc_ns_actor,rc_actor,rc_namespace_title_timestamp,rc_this_oldid | tmp_2                 | 1       | const                                                                 | 4274159 | Using where |
|    1 | PRIMARY            | watchlist          | eq_ref | wl_user,namespace_title,wl_user_notificationtimestamp                                                                                        | wl_user               | 265     | const,enwiki.recentchanges.rc_namespace,enwiki.recentchanges.rc_title | 1       |             |
|    1 | PRIMARY            | actor_rc_user      | eq_ref | PRIMARY,actor_user                                                                                                                           | PRIMARY               | 8       | enwiki.recentchanges.rc_actor                                         | 1       |             |
|    1 | PRIMARY            | user               | eq_ref | PRIMARY                                                                                                                                      | PRIMARY               | 4       | enwiki.actor_rc_user.actor_user                                       | 1       | Using where |
|    1 | PRIMARY            | page               | eq_ref | PRIMARY                                                                                                                                      | PRIMARY               | 4       | enwiki.recentchanges.rc_cur_id                                        | 1       | Using where |
|    1 | PRIMARY            | flaggedpages       | eq_ref | PRIMARY                                                                                                                                      | PRIMARY               | 4       | enwiki.recentchanges.rc_cur_id                                        | 1       |             |
|    1 | PRIMARY            | ores_damaging_cls  | eq_ref | oresc_rev_model_class                                                                                                                        | oresc_rev_model_class | 7       | enwiki.recentchanges.rc_this_oldid,const,const                        | 1       |             |
|    1 | PRIMARY            | ores_goodfaith_cls | eq_ref | oresc_rev_model_class                                                                                                                        | oresc_rev_model_class | 7       | enwiki.recentchanges.rc_this_oldid,const,const                        | 1       |             |
|    1 | PRIMARY            | comment_rc_comment | eq_ref | PRIMARY                                                                                                                                      | PRIMARY               | 8       | enwiki.recentchanges.rc_comment_id                                    | 1       |             |
|    2 | DEPENDENT SUBQUERY | change_tag         | ref    | change_tag_rc_tag_id,change_tag_tag_id_id                                                                                                    | change_tag_rc_tag_id  | 5       | enwiki.recentchanges.rc_id                                            | 1       | Using index |
|    2 | DEPENDENT SUBQUERY | change_tag_def     | eq_ref | PRIMARY                                                                                                                                      | PRIMARY               | 4       | enwiki.change_tag.ct_tag_id                                           | 1       |             |
+------+--------------------+--------------------+--------+----------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+---------+-----------------------------------------------------------------------+---------+-------------+
11 rows in set (0.00 sec)

It is picking tmp_2 as an index, while 10.1 picks tmp_3, which is a lot better:

+------+--------------------+--------------------+--------+----------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+---------+-----------------------------------------------------------------------+------+----------------------------------------------------+
| id   | select_type        | table              | type   | possible_keys                                                                                                                                | key                   | key_len | ref                                                                   | rows | Extra                                              |
+------+--------------------+--------------------+--------+----------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+---------+-----------------------------------------------------------------------+------+----------------------------------------------------+
|    1 | PRIMARY            | recentchanges      | range  | rc_timestamp,new_name_timestamp,tmp_2,tmp_3,rc_name_type_patrolled_timestamp,rc_ns_actor,rc_actor,rc_namespace_title_timestamp,rc_this_oldid | tmp_3                 | 20      | NULL                                                                  |  958 | Using index condition; Using where; Using filesort |
|    1 | PRIMARY            | watchlist          | eq_ref | wl_user,namespace_title,wl_user_notificationtimestamp                                                                                        | wl_user               | 265     | const,enwiki.recentchanges.rc_namespace,enwiki.recentchanges.rc_title |    1 |                                                    |
|    1 | PRIMARY            | actor_rc_user      | eq_ref | PRIMARY,actor_user                                                                                                                           | PRIMARY               | 8       | enwiki.recentchanges.rc_actor                                         |    1 |                                                    |
|    1 | PRIMARY            | user               | eq_ref | PRIMARY                                                                                                                                      | PRIMARY               | 4       | enwiki.actor_rc_user.actor_user                                       |    1 | Using where                                        |
|    1 | PRIMARY            | page               | eq_ref | PRIMARY                                                                                                                                      | PRIMARY               | 4       | enwiki.recentchanges.rc_cur_id                                        |    1 | Using where                                        |
|    1 | PRIMARY            | flaggedpages       | eq_ref | PRIMARY                                                                                                                                      | PRIMARY               | 4       | enwiki.recentchanges.rc_cur_id                                        |    1 |                                                    |
|    1 | PRIMARY            | ores_damaging_cls  | eq_ref | oresc_rev_model_class                                                                                                                        | oresc_rev_model_class | 7       | enwiki.recentchanges.rc_this_oldid,const,const                        |    1 |                                                    |
|    1 | PRIMARY            | ores_goodfaith_cls | eq_ref | oresc_rev_model_class                                                                                                                        | oresc_rev_model_class | 7       | enwiki.recentchanges.rc_this_oldid,const,const                        |    1 |                                                    |
|    1 | PRIMARY            | comment_rc_comment | eq_ref | PRIMARY                                                                                                                                      | PRIMARY               | 8       | enwiki.recentchanges.rc_comment_id                                    |    1 |                                                    |
|    2 | DEPENDENT SUBQUERY | change_tag         | ref    | change_tag_rc_tag_id,change_tag_tag_id_id                                                                                                    | change_tag_rc_tag_id  | 5       | enwiki.recentchanges.rc_id                                            |    1 | Using index                                        |
|    2 | DEPENDENT SUBQUERY | change_tag_def     | eq_ref | PRIMARY                                                                                                                                      | PRIMARY               | 4       | enwiki.change_tag.ct_tag_id                                           |    1 |                                                    |
+------+--------------------+--------------------+--------+----------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+---------+-----------------------------------------------------------------------+------+----------------------------------------------------+

The optimize trace actually shows that tmp_3 index is a better election, but it chooses tmp_2 anyways:

{
                       "index": "tmp_2",
                       "ranges": ["(0,020200224144839) <= (rc_bot,rc_timestamp)"],
                       "rowid_ordered": false,
                       "using_mrr": false,
                       "index_only": false,
                       "rows": 405574,
                       "cost": 508110,
                       "chosen": false,
                       "cause": "cost"
                     },
                     {
                       "index": "tmp_3",
                       "ranges": [
                         "(6,620200224144839) <= (rc_namespace,rc_timestamp)",
                         "(7,720200224144839) <= (rc_namespace,rc_timestamp)"
                       ],
                       "rowid_ordered": false,
                       "using_mrr": false,
                       "index_only": false,
                       "rows": 957,
                       "cost": 1201,
                       "chosen": true

           "considered_execution_plans": [
             {
               "plan_prefix": [],
               "table": "recentchanges",
               "best_access_path": {
                 "considered_access_paths": [
                   {
                     "access_type": "ref",
                     "index": "tmp_2",
                     "rows": 4.27e6,
                     "cost": 440644,
                     "chosen": true
                   },

Full optimizer trace at P10509#60991

root@db1107.eqiad.wmnet[(none)]> show explain for 324762816;
+------+--------------------+--------------------+--------+----------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+---------+-----------------------------------------------------------------------+---------+-------------+
| id   | select_type        | table              | type   | possible_keys                                                                                                                                | key                   | key_len | ref                                                                   | rows    | Extra       |
+------+--------------------+--------------------+--------+----------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+---------+-----------------------------------------------------------------------+---------+-------------+
|    1 | PRIMARY            | recentchanges      | ref    | rc_timestamp,new_name_timestamp,tmp_2,tmp_3,rc_name_type_patrolled_timestamp,rc_ns_actor,rc_actor,rc_namespace_title_timestamp,rc_this_oldid | tmp_2                 | 1       | const                                                                 | 4262230 | Using where |
|    1 | PRIMARY            | watchlist          | eq_ref | wl_user,namespace_title,wl_user_notificationtimestamp                                                                                        | wl_user               | 265     | const,enwiki.recentchanges.rc_namespace,enwiki.recentchanges.rc_title |       1 |             |
|    1 | PRIMARY            | actor_rc_user      | eq_ref | PRIMARY,actor_user                                                                                                                           | PRIMARY               | 8       | enwiki.recentchanges.rc_actor                                         |       1 |             |
|    1 | PRIMARY            | user               | eq_ref | PRIMARY                                                                                                                                      | PRIMARY               | 4       | enwiki.actor_rc_user.actor_user                                       |       1 | Using where |
|    1 | PRIMARY            | page               | eq_ref | PRIMARY                                                                                                                                      | PRIMARY               | 4       | enwiki.recentchanges.rc_cur_id                                        |       1 | Using where |
|    1 | PRIMARY            | flaggedpages       | eq_ref | PRIMARY                                                                                                                                      | PRIMARY               | 4       | enwiki.recentchanges.rc_cur_id                                        |       1 |             |
|    1 | PRIMARY            | ores_damaging_cls  | eq_ref | oresc_rev_model_class                                                                                                                        | oresc_rev_model_class | 7       | enwiki.recentchanges.rc_this_oldid,const,const                        |       1 |             |
|    1 | PRIMARY            | ores_goodfaith_cls | eq_ref | oresc_rev_model_class                                                                                                                        | oresc_rev_model_class | 7       | enwiki.recentchanges.rc_this_oldid,const,const                        |       1 |             |
|    1 | PRIMARY            | comment_rc_comment | eq_ref | PRIMARY                                                                                                                                      | PRIMARY               | 8       | enwiki.recentchanges.rc_comment_id                                    |       1 |             |
|    2 | DEPENDENT SUBQUERY | change_tag         | ref    | change_tag_rc_tag_id,change_tag_tag_id_id                                                                                                    | change_tag_rc_tag_id  | 5       | enwiki.recentchanges.rc_id                                            |       1 | Using index |
|    2 | DEPENDENT SUBQUERY | change_tag_def     | eq_ref | PRIMARY                                                                                                                                      | PRIMARY               | 4       | enwiki.change_tag.ct_tag_id                                           |       1 |             |
+------+--------------------+--------------------+--------+----------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+---------+-----------------------------------------------------------------------+---------+-------------+
11 rows in set, 1 warning (0.01 sec)

Forcing index tmp_3 on 10.4 shows the same result than on 10.1 and a lot faster query 12 seconds vs 0.02 query runtime even though it does failsort
Explain

+------+--------------------+--------------------+--------+-------------------------------------------------------+-----------------------+---------+-----------------------------------------------------------------------+------+----------------------------------------------------+
| id   | select_type        | table              | type   | possible_keys                                         | key                   | key_len | ref                                                                   | rows | Extra                                              |
+------+--------------------+--------------------+--------+-------------------------------------------------------+-----------------------+---------+-----------------------------------------------------------------------+------+----------------------------------------------------+
|    1 | PRIMARY            | recentchanges      | range  | tmp_3                                                 | tmp_3                 | 20      | NULL                                                                  | 962  | Using index condition; Using where; Using filesort |
|    1 | PRIMARY            | watchlist          | eq_ref | wl_user,namespace_title,wl_user_notificationtimestamp | wl_user               | 265     | const,enwiki.recentchanges.rc_namespace,enwiki.recentchanges.rc_title | 1    |                                                    |
|    1 | PRIMARY            | actor_rc_user      | eq_ref | PRIMARY,actor_user                                    | PRIMARY               | 8       | enwiki.recentchanges.rc_actor                                         | 1    |                                                    |
|    1 | PRIMARY            | user               | eq_ref | PRIMARY                                               | PRIMARY               | 4       | enwiki.actor_rc_user.actor_user                                       | 1    | Using where                                        |
|    1 | PRIMARY            | page               | eq_ref | PRIMARY                                               | PRIMARY               | 4       | enwiki.recentchanges.rc_cur_id                                        | 1    | Using where                                        |
|    1 | PRIMARY            | flaggedpages       | eq_ref | PRIMARY                                               | PRIMARY               | 4       | enwiki.recentchanges.rc_cur_id                                        | 1    |                                                    |
|    1 | PRIMARY            | ores_damaging_cls  | eq_ref | oresc_rev_model_class                                 | oresc_rev_model_class | 7       | enwiki.recentchanges.rc_this_oldid,const,const                        | 1    |                                                    |
|    1 | PRIMARY            | ores_goodfaith_cls | eq_ref | oresc_rev_model_class                                 | oresc_rev_model_class | 7       | enwiki.recentchanges.rc_this_oldid,const,const                        | 1    |                                                    |
|    1 | PRIMARY            | comment_rc_comment | eq_ref | PRIMARY                                               | PRIMARY               | 8       | enwiki.recentchanges.rc_comment_id                                    | 1    |                                                    |
|    2 | DEPENDENT SUBQUERY | change_tag         | ref    | change_tag_rc_tag_id,change_tag_tag_id_id             | change_tag_rc_tag_id  | 5       | enwiki.recentchanges.rc_id                                            | 1    | Using index                                        |
|    2 | DEPENDENT SUBQUERY | change_tag_def     | eq_ref | PRIMARY                                               | PRIMARY               | 4       | enwiki.change_tag.ct_tag_id                                           | 1    |                                                    |
+------+--------------------+--------------------+--------+-------------------------------------------------------+-----------------------+---------+-----------------------------------------------------------------------+------+----------------------------------------------------+
11 rows in set (0.01 sec)

Event Timeline

Marostegui triaged this task as Medium priority.Feb 25 2020, 7:36 AM
Marostegui created this task.
Marostegui moved this task from Triage to In progress on the DBA board.
Marostegui added a subscriber: Anomie.

I am going to report this to MariaDB

Another comparison with the JSON output
Normal run:

"query_block": {
   "select_id": 1,
   "r_loops": 1,
   "r_total_time_ms": 12905,
   "table": {
     "table_name": "recentchanges",
     "access_type": "ref",
     "possible_keys": [
       "rc_timestamp",
       "new_name_timestamp",
       "tmp_2",
       "tmp_3",
       "rc_name_type_patrolled_timestamp",
       "rc_ns_actor",
       "rc_actor",
       "rc_namespace_title_timestamp",
       "rc_this_oldid"
     ],
     "key": "tmp_2",
     "key_length": "1",
     "used_key_parts": ["rc_bot"],
     "ref": ["const"],
     "r_loops": 1,
     "rows": 4274159,
     "r_rows": 7.28e6,
     "r_total_time_ms": 11593,
     "filtered": 0.0113,
     "r_filtered": 0.0091,
     "attached_condition": "recentchanges.rc_b

Using a USE INDEX (tmp_3):

"query_block": {
   "select_id": 1,
   "r_loops": 1,
   "r_total_time_ms": 13.483,
   "read_sorted_file": {
     "r_rows": 663,
     "filesort": {
       "sort_key": "recentchanges.rc_timestamp desc",
       "r_loops": 1,
       "r_total_time_ms": 5.9206,
       "r_used_priority_queue": false,
       "r_output_rows": 663,
       "r_buffer_size": "2047Kb",
       "table": {
         "table_name": "recentchanges",
         "access_type": "range",
         "possible_keys": ["tmp_3"],
         "key": "tmp_3",
         "key_length": "20",
         "used_key_parts": ["rc_namespace", "rc_timestamp"],
         "r_loops": 1,
         "rows": 967,
         "r_rows": 967,
         "r_total_time_ms": 6.7351,
         "filtered": 83.716,
         "r_filtered": 68.563,
         "index_condition": "recentchanges.rc_namespace in ('6','7') and recentchanges.rc_timestamp >= '20200224144839'",
         "attached_condition": "recentchanges.rc_bot = 0 and recentchanges.rc_type <> 6 and recentchanges.rc_source <> 'wb' and recentchanges.rc_new in (0,1)"
       }

I note that neither tmp_2 nor tmp_3 are in tables.sql. See also T206103: recentchanges table indexes: tmp1, tmp2 and tmp3.

None of the possible queries here really seem all that good. tmp_2 has pretty low selectivity with the rc_bot = 0, and winds up touching 7 million rows to find the 6 that match. tmp_3 turns out to have much better selectivity on rc_namespace IN ('6', '7'), so even though it filesorts it only winds up touching a few thousand. Ignoring both tmp_2 and tmp_3 so as to use only indexes in tables.sql chooses new_name_timestamp, which filesorts like tmp_3 and also has the good selectivity for this particular query.

I'm not sure what we could do on the MediaWiki side to try to work around this, as this query looks like it will be very sensitive to the specifics. Change rc_namespace IN ('6', '7') to rc_namespace IN ('0, '1'), for example, and the selectivity will go way down (and matching rows way up) which would probably make tmp_2 a better choice here (when I try it, tmp_2 completes in fractions of a second, and ignoring tmp_2 it falls back to rc_timestamp which also goes really fast).

Yes, those indexed are meant to be removed, but last time I checked they are indeed being used (as we saw here).
We can probably try to get a host and remove them and check if we have some regressions.

In this particular case, I'm surprised to see the optimizer choosing the index with the higher number of rows and cost. So we'll see if mariadb says something about it.

There's been movement on this bug: https://jira.mariadb.org/browse/MDEV-21813?focusedCommentId=146969&page=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel#comment-146969

(Setting fixVersion to be 10.4, for now. I'm not actually sure if we'll be able to fix this in 10.4, but lets be optimistic)

This keeps happening on 10.6 from what I can tell

Removing task assignee due to inactivity as this open task has been assigned for more than two years. See the email sent to the task assignee on August 22nd, 2022.
Please assign this task to yourself again if you still realistically [plan to] work on this task - it would be welcome!
If this task has been resolved in the meantime, or should not be worked on ("declined"), please update its task status via "Add Action… 🡒 Change Status".
Also see https://www.mediawiki.org/wiki/Bug_management/Assignee_cleanup for tips how to best manage your individual work in Phabricator. Thanks!

This seems to be fixed on MariaDB 10.6.10 (and mariadb 11), it takes 0.5 seconds.

I am going to close this as fixed, given that this will automatically get fixed once we are on 10.6. And we aren't going to make any changes to the query itself as of now.