[MDEV-28476] Optimizer picking up wrong index on 10.6 but not on 10.4 Created: 2022-05-05  Updated: 2022-06-02

Status: Open
Project: MariaDB Server
Component/s: Optimizer
Affects Version/s: 10.6.7
Fix Version/s: 10.6

Type: Bug Priority: Major
Reporter: Manuel Arostegui Assignee: Sergei Petrunia
Resolution: Unresolved Votes: 0
Labels: None
Environment:

debian bullseye



 Description   

We have one host running 10.6.7 where a query takes more than 40 seconds to run, whereas it takes 0.009 on 10.4.21

Query:

SELECT  actor_name,actor_user,rc_actor,rc_id,rc_timestamp,rc_namespace,rc_title,rc_cur_id,rc_type,rc_deleted,rc_this_oldid,rc_last_oldid,comment_rc_comment.comment_text AS `rc_comment_text`,comment_rc_comment.comment_data AS `rc_comment_data`,comment_rc_comment.comment_id AS `rc_comment_cid`  FROM `recentchanges` JOIN `actor` ON ((actor_id=rc_actor)) JOIN `comment` `comment_rc_comment` ON ((comment_rc_comment.comment_id = rc_comment_id))   WHERE rc_namespace = 0 AND rc_type IN (0,1,3,6)   ORDER BY rc_timestamp DESC,rc_id DESC LIMIT 501  ;

Involved tables:

 
mysql:root@localhost [enwiki]> show create table recentchanges\G show create table actor\G show create table comment\G
*************************** 1. row ***************************
       Table: recentchanges
Create Table: CREATE TABLE `recentchanges` (
  `rc_id` int(10) unsigned NOT NULL AUTO_INCREMENT,
  `rc_timestamp` binary(14) NOT NULL,
  `rc_actor` bigint(20) unsigned NOT NULL,
  `rc_namespace` int(11) NOT NULL DEFAULT 0,
  `rc_title` varbinary(255) NOT NULL DEFAULT '',
  `rc_comment_id` bigint(20) unsigned NOT NULL,
  `rc_minor` tinyint(3) unsigned NOT NULL DEFAULT 0,
  `rc_bot` tinyint(3) unsigned NOT NULL DEFAULT 0,
  `rc_new` tinyint(3) unsigned NOT NULL DEFAULT 0,
  `rc_cur_id` int(10) unsigned NOT NULL DEFAULT 0,
  `rc_this_oldid` int(10) unsigned NOT NULL DEFAULT 0,
  `rc_last_oldid` int(10) unsigned NOT NULL DEFAULT 0,
  `rc_type` tinyint(3) unsigned NOT NULL DEFAULT 0,
  `rc_source` varbinary(16) NOT NULL DEFAULT '',
  `rc_patrolled` tinyint(3) unsigned NOT NULL DEFAULT 0,
  `rc_ip` varbinary(40) NOT NULL DEFAULT '',
  `rc_old_len` int(10) DEFAULT NULL,
  `rc_new_len` int(10) DEFAULT NULL,
  `rc_deleted` tinyint(1) unsigned NOT NULL DEFAULT 0,
  `rc_logid` int(10) unsigned NOT NULL DEFAULT 0,
  `rc_log_type` varbinary(255) DEFAULT NULL,
  `rc_log_action` varbinary(255) DEFAULT NULL,
  `rc_params` blob DEFAULT NULL,
  PRIMARY KEY (`rc_id`),
  KEY `rc_timestamp` (`rc_timestamp`),
  KEY `rc_cur_id` (`rc_cur_id`),
  KEY `rc_ip` (`rc_ip`),
  KEY `rc_name_type_patrolled_timestamp` (`rc_namespace`,`rc_type`,`rc_patrolled`,`rc_timestamp`),
  KEY `rc_ns_actor` (`rc_namespace`,`rc_actor`),
  KEY `rc_actor` (`rc_actor`,`rc_timestamp`),
  KEY `rc_namespace_title_timestamp` (`rc_namespace`,`rc_title`,`rc_timestamp`),
  KEY `rc_this_oldid` (`rc_this_oldid`),
  KEY `rc_new_name_timestamp` (`rc_new`,`rc_namespace`,`rc_timestamp`)
) ENGINE=InnoDB AUTO_INCREMENT=1502489802 DEFAULT CHARSET=binary ROW_FORMAT=COMPRESSED
1 row in set (0.000 sec)
 
*************************** 1. row ***************************
       Table: actor
Create Table: CREATE TABLE `actor` (
  `actor_id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `actor_user` int(10) unsigned DEFAULT NULL,
  `actor_name` varbinary(255) NOT NULL,
  PRIMARY KEY (`actor_id`),
  UNIQUE KEY `actor_name` (`actor_name`),
  UNIQUE KEY `actor_user` (`actor_user`)
) ENGINE=InnoDB AUTO_INCREMENT=219460700 DEFAULT CHARSET=binary ROW_FORMAT=COMPRESSED
1 row in set (0.000 sec)
 
*************************** 1. row ***************************
       Table: comment
Create Table: CREATE TABLE `comment` (
  `comment_id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `comment_hash` int(11) NOT NULL,
  `comment_text` blob NOT NULL,
  `comment_data` blob DEFAULT NULL,
  PRIMARY KEY (`comment_id`),
  KEY `comment_hash` (`comment_hash`)
) ENGINE=InnoDB AUTO_INCREMENT=392012245 DEFAULT CHARSET=binary ROW_FORMAT=COMPRESSED
1 row in set (0.000 sec)

Explain on 10.6

root@db1132.eqiad.wmnet[enwiki]> select @@version; explain SELECT  actor_name,actor_user,rc_actor,rc_id,rc_timestamp,rc_namespace,rc_title,rc_cur_id,rc_type,rc_deleted,rc_this_oldid,rc_last_oldid,comment_rc_comment.comment_text AS `rc_comment_text`,comment_rc_comment.comment_data AS `rc_comment_data`,comment_rc_comment.comment_id AS `rc_comment_cid`  FROM `recentchanges` JOIN `actor` ON ((actor_id=rc_actor)) JOIN `comment` `comment_rc_comment` ON ((comment_rc_comment.comment_id = rc_comment_id))   WHERE rc_namespace = 0 AND rc_type IN (0,1,3,6)   ORDER BY rc_timestamp DESC,rc_id DESC LIMIT 501  ;
+--------------------+
| @@version          |
+--------------------+
| 10.6.7-MariaDB-log |
+--------------------+
1 row in set (0.001 sec)
 
+------+-------------+--------------------+--------+------------------------------------------------------------------------------------+----------------------------------+---------+------------------------------------+---------+------------------------------------------>
| id   | select_type | table              | type   | possible_keys                                                                      | key                              | key_len | ref                                | rows    | Extra                                    >
+------+-------------+--------------------+--------+------------------------------------------------------------------------------------+----------------------------------+---------+------------------------------------+---------+------------------------------------------>
|    1 | SIMPLE      | recentchanges      | ref    | rc_name_type_patrolled_timestamp,rc_ns_actor,rc_actor,rc_namespace_title_timestamp | rc_name_type_patrolled_timestamp | 4       | const                              | 5190120 | Using index condition; Using where; Using>
|    1 | SIMPLE      | actor              | eq_ref | PRIMARY                                                                            | PRIMARY                          | 8       | enwiki.recentchanges.rc_actor      | 1       |                                          >
|    1 | SIMPLE      | comment_rc_comment | eq_ref | PRIMARY                                                                            | PRIMARY                          | 8       | enwiki.recentchanges.rc_comment_id | 1       |                                          >
+------+-------------+--------------------+--------+------------------------------------------------------------------------------------+----------------------------------+---------+------------------------------------+---------+------------------------------------------>
3 rows in set (0.001 sec)

Explain on 10.4.21

mysql:root@localhost [enwiki]>  select @@version; explain SELECT  actor_name,actor_user,rc_actor,rc_id,rc_timestamp,rc_namespace,rc_title,rc_cur_id,rc_type,rc_deleted,rc_this_oldid,rc_last_oldid,comment_rc_comment.comment_text AS `rc_comment_text`,comment_rc_comment.comment_data AS `rc_comment_data`,comment_rc_comment.comment_id AS `rc_comment_cid`  FROM `recentchanges` JOIN `actor` ON ((actor_id=rc_actor)) JOIN `comment` `comment_rc_comment` ON ((comment_rc_comment.comment_id = rc_comment_id))   WHERE rc_namespace = 0 AND rc_type IN (0,1,3,6)   ORDER BY rc_timestamp DESC,rc_id DESC LIMIT 501  ;
+---------------------+
| @@version           |
+---------------------+
| 10.4.21-MariaDB-log |
+---------------------+
1 row in set (0.000 sec)
 
+------+-------------+--------------------+--------+------------------------------------------------------------------------------------+--------------+---------+------------------------------------+------+-------------+
| id   | select_type | table              | type   | possible_keys                                                                      | key          | key_len | ref                                | rows | Extra       |
+------+-------------+--------------------+--------+------------------------------------------------------------------------------------+--------------+---------+------------------------------------+------+-------------+
|    1 | SIMPLE      | recentchanges      | index  | rc_name_type_patrolled_timestamp,rc_ns_actor,rc_actor,rc_namespace_title_timestamp | rc_timestamp | 14      | NULL                               | 1002 | Using where |
|    1 | SIMPLE      | actor              | eq_ref | PRIMARY                                                                            | PRIMARY      | 8       | enwiki.recentchanges.rc_actor      | 1    |             |
|    1 | SIMPLE      | comment_rc_comment | eq_ref | PRIMARY                                                                            | PRIMARY      | 8       | enwiki.recentchanges.rc_comment_id | 1    |             |
+------+-------------+--------------------+--------+------------------------------------------------------------------------------------+--------------+---------+------------------------------------+------+-------------+
3 rows in set (0.001 sec)

If we force to use rc_timestamp index on 10.6.7 the query flies:

root@db1132.eqiad.wmnet[enwiki]> select @@version; explain SELECT  actor_name,actor_user,rc_actor,rc_id,rc_timestamp,rc_namespace,rc_title,rc_cur_id,rc_type,rc_deleted,rc_this_oldid,rc_last_oldid,comment_rc_comment.comment_text AS `rc_comment_text`,comment_rc_comment.comment_data AS `rc_comment_data`,comment_rc_comment.comment_id AS `rc_comment_cid`  FROM `recentchanges` USE INDEX (rc_timestamp) JOIN `actor` ON ((actor_id=rc_actor)) JOIN `comment` `comment_rc_comment` ON ((comment_rc_comment.comment_id = rc_comment_id))   WHERE rc_namespace = 0 AND rc_type IN (0,1,3,6)   ORDER BY rc_timestamp DESC,rc_id DESC LIMIT 501  ;
+--------------------+
| @@version          |
+--------------------+
| 10.6.7-MariaDB-log |
+--------------------+
1 row in set (0.000 sec)
 
+------+-------------+--------------------+--------+---------------+--------------+---------+------------------------------------+------+-------------+
| id   | select_type | table              | type   | possible_keys | key          | key_len | ref                                | rows | Extra       |
+------+-------------+--------------------+--------+---------------+--------------+---------+------------------------------------+------+-------------+
|    1 | SIMPLE      | recentchanges      | index  | NULL          | rc_timestamp | 14      | NULL                               | 1298 | Using where |
|    1 | SIMPLE      | actor              | eq_ref | PRIMARY       | PRIMARY      | 8       | enwiki.recentchanges.rc_actor      | 1    |             |
|    1 | SIMPLE      | comment_rc_comment | eq_ref | PRIMARY       | PRIMARY      | 8       | enwiki.recentchanges.rc_comment_id | 1    |             |
+------+-------------+--------------------+--------+---------------+--------------+---------+------------------------------------+------+-------------+
3 rows in set (0.001 sec)

Refreshing the table stats made no difference, these are the analyze output for the 10.6 host:

ANALYZE: {
  "query_block": {
    "select_id": 1,
    "r_loops": 1,
    "r_total_time_ms": 20610.43199,
    "read_sorted_file": {
      "r_rows": 501,
      "filesort": {
        "sort_key": "recentchanges.rc_timestamp desc, recentchanges.rc_id desc",
        "r_loops": 1,
        "r_total_time_ms": 20585.62658,
        "r_used_priority_queue": false,
        "r_output_rows": 3412068,
        "r_sort_passes": 28,
        "r_buffer_size": "2047Kb",
        "r_sort_mode": "sort_key,packed_addon_fields",
        "table": {
          "table_name": "recentchanges",
          "access_type": "ref",
          "possible_keys": [
            "rc_name_type_patrolled_timestamp",
            "rc_ns_actor",
            "rc_actor",
            "rc_namespace_title_timestamp"
          ],
          "key": "rc_name_type_patrolled_timestamp",
          "key_length": "4",
          "used_key_parts": ["rc_namespace"],
          "ref": ["const"],
          "r_loops": 1,
          "rows": 5190268,
          "r_rows": 3412068,
          "r_table_time_ms": 13434.23499,
          "r_other_time_ms": 7078.505105,
          "filtered": 85.9375,
          "r_filtered": 100,
          "index_condition": "recentchanges.rc_type in (0,1,3,6)",
          "attached_condition": "recentchanges.rc_namespace <=> 0"
        }
      }
    },
    "table": {
      "table_name": "actor",
      "access_type": "eq_ref",
      "possible_keys": ["PRIMARY"],
      "key": "PRIMARY",
      "key_length": "8",
      "used_key_parts": ["actor_id"],
      "ref": ["enwiki.recentchanges.rc_actor"],
      "r_loops": 501,
      "rows": 1,
      "r_rows": 1,
      "r_table_time_ms": 2.416486026,
      "r_other_time_ms": 0.080633079,
      "filtered": 100,
      "r_filtered": 100
    },
    "table": {
      "table_name": "comment_rc_comment",
      "access_type": "eq_ref",
      "possible_keys": ["PRIMARY"],
      "key": "PRIMARY",
      "key_length": "8",
      "used_key_parts": ["comment_id"],
      "ref": ["enwiki.recentchanges.rc_comment_id"],
      "r_loops": 501,
      "rows": 1,
      "r_rows": 1,
      "r_table_time_ms": 2.425323757,
      "r_other_time_ms": 19.83621405,
      "filtered": 100,
      "r_filtered": 100
    }
  }
}

Analyze for 10.4.21:

*************************** 1. row ***************************
ANALYZE: {
  "query_block": {
    "select_id": 1,
    "r_loops": 1,
    "r_total_time_ms": 15.122,
    "table": {
      "table_name": "recentchanges",
      "access_type": "index",
      "possible_keys": [
        "rc_name_type_patrolled_timestamp",
        "rc_ns_actor",
        "rc_actor",
        "rc_namespace_title_timestamp"
      ],
      "key": "rc_timestamp",
      "key_length": "14",
      "used_key_parts": ["rc_timestamp"],
      "ref": ["const"],
      "r_loops": 1,
      "rows": 8960755,
      "r_rows": 1478,
      "r_total_time_ms": 7.6369,
      "filtered": 50,
      "r_filtered": 33.897,
      "attached_condition": "recentchanges.rc_namespace <=> 0 and recentchanges.rc_type in (0,1,3,6)"
    },
    "table": {
      "table_name": "actor",
      "access_type": "eq_ref",
      "possible_keys": ["PRIMARY"],
      "key": "PRIMARY",
      "key_length": "8",
      "used_key_parts": ["actor_id"],
      "ref": ["enwiki.recentchanges.rc_actor"],
      "r_loops": 501,
      "rows": 1,
      "r_rows": 1,
      "r_total_time_ms": 3.3496,
      "filtered": 100,
      "r_filtered": 100
    },
    "table": {
      "table_name": "comment_rc_comment",
      "access_type": "eq_ref",
      "possible_keys": ["PRIMARY"],
      "key": "PRIMARY",
      "key_length": "8",
      "used_key_parts": ["comment_id"],
      "ref": ["enwiki.recentchanges.rc_comment_id"],
      "r_loops": 501,
      "rows": 1,
      "r_rows": 1,
      "r_total_time_ms": 2.814,
      "filtered": 100,
      "r_filtered": 100
    }
  }
}
1 row in set (0.016 sec)

Optimizer trace for 10.6 host: https://phabricator.wikimedia.org/P27619
Optimizer trace for 10.4 host: https://phabricator.wikimedia.org/P27617



 Comments   
Comment by Marko Mäkelä [ 2022-05-05 ]

Hi marostegui, if the underlying cause of this is that the InnoDB persistent statistics are not being updated, then this report could be a duplicate of MDEV-27805. Due to a race condition, the InnoDB statistics recalculation queue could lose some events.

Would ANALYZE TABLE fix the query plan?

Comment by Marko Mäkelä [ 2022-05-05 ]

Oh, sorry, I should have read the full description. ANALYZE TABLE was attempted and did not make a difference.

Comment by Manuel Arostegui [ 2022-05-05 ]

hehe, yeah marko that was the first thing I tried once I saw it.

Generated at Thu Feb 08 10:01:03 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.