mysql慢查询分析实战 -- 一次奇怪的线上问题

521 阅读3分钟

昨晚线上似乎出了点事,老大半夜被dba叫醒说有sql慢查询,所有地区都是这样,最后在和dba的合作支持下临时解决了问题,今天早上一过来老大就让我看下慢查询原因,分析一下防止之后出现问题。

1. 问题描述

我们有个业务是推送消息广播的,就是卖家创建一条定时广播,然后在指定时间我们把这个广播推给买家,于是有个服务专门从DB中定时扫表取出需要推送的广播,放在缓存中给另另一个服务推送用。

下面是简化的表结构:

CREATE TABLE `push_tab` (
  `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT COMMENT 'primary ID',
  `shop_id` int(10) unsigned NOT NULL COMMENT 'shop ID',
  `push_time` int(10) unsigned NOT NULL COMMENT 'push time',
  `plan_flag` int(10) unsigned NOT NULL COMMENT 'plan flag',
  `is_delete` tinyint(1) NOT NULL COMMENT 'delete mark',
  `region` char(10) COLLATE utf8mb4_unicode_ci NOT NULL DEFAULT '',
  PRIMARY KEY (`id`),
  KEY `idx_push_time` (`push_time`),
  KEY `idx_planflag_isdelete_region_pushtime` (`plan_flag`,`is_delete`,`region`,`push_time`)
) ENGINE=InnoDB AUTO_INCREMENT=10075830 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci;

我们采集广播的sql类似于:

SELECT
	*
FROM
	push_tab
WHERE
	is_delete = 0
	and push_time<1668010460
	and region = 'us'
	and plan_flag in (0, 1)
order by
	push_time desc
limit 66 offset 0;

比较普通的一个sql,我们是期望他走idx_planflag_isdelete_region_pushtime这个索引的,正常情况下也确实会走这个索引,但是昨晚出问题时走的是idx_push_time这个索引,这里造点实验数据来模拟。

2. 实验

模拟线上的数据分布比例,这里只模拟一个地区,is_delete=1的数据少的几乎可以忽略,主要是push_time随机分布,plan_flag按比例分布,大概如下:

plan_flag数量
01500
2100
310000
4100

这时候explain下sql:

mysql> explain select * from push_tab where is_delete = 0 and push_time<1668010460 and region = 'us' and plan_flag in (0, 1) order by push_time desc limit 66 offset 0\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: push_tab
   partitions: NULL
         type: range
possible_keys: idx_push_time,idx_planflag_isdelete_region_pushtime
          key: idx_push_time
      key_len: 4
          ref: NULL
         rows: 5817
     filtered: 0.20
        Extra: Using index condition; Using where
1 row in set, 1 warning (0.00 sec)

可以看到虽然idx_planflag_isdelete_region_pushtime完美契合where语句,但是并不会走这个index,而是走了idx_push_time,此时的push_time区分度其实是不高的,rows是5817行,几乎是所有记录数的一半了。线上的数据自然是很多的,走了这个索引可想而知sql是有多慢。

但是诡异的点是在于业务运行一会后索引的选择就会变得正常,此时的数据集情况大概是plan_flag=0⬇️,plan_flag=3⬆️,如下:

plan_flag数量
0600
2100
310900
4100

此时再explain一下sql:

mysql> explain select * from push_tab where is_delete = 0 and push_time<1668010460 and region = 'us' and plan_flag in (0, 1) order by push_time desc limit 1000 offset 0\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: push_tab
   partitions: NULL
         type: range
possible_keys: idx_push_time,idx_planflag_isdelete_region_pushtime
          key: idx_planflag_isdelete_region_pushtime
      key_len: 49
          ref: NULL
         rows: 601
     filtered: 100.00
        Extra: Using index condition; Using filesort
1 row in set, 1 warning (0.41 sec)

可以看到又采用了我们期望的index,并且可以通过调整实验集得知,在一个临界值下,plan_flag=0的数据量大于等于这个值就会用错误的索引,小于这个值会采用正确的索引。

3. 分析

这个场景用explain已经看不出什么了, 需要知道mysql的每一步优化步骤了, 比较方便的方式如下:

SET optimizer_trace="enabled=on";
-- 在这里写需要分析的sql
SELECT * FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE;

这样每次查询一次sql就可以在NFORMATION_SCHEMA.OPTIMIZER_TRACE这个表的TRACE字段里取出mysql的优化步骤,格式是json的也比较容易查看。

需要注意的是得把optimizer_trace_max_mem_size这个变量设置高一点,不然TRACE字段会被截断,我这里使用了set global optimizer_trace_max_mem_size = 65536 设置成了64k,够我这次用了。

trace json比较长,这里不太方便全粘贴出来,只粘贴关键的部分:

{
    "considered_execution_plans": [
        {
            "plan_prefix": [],
            "table": "`push_tab`",
            "best_access_path": {
                "considered_access_paths": [
                    {
                        "rows_to_scan": 1501,
                        "access_type": "range",
                        "range_details": {
                            "used_index": "idx_planflag_isdelete_region_pushtime"
                        },
                        "resulting_rows": 1501,
                        "cost": 2103.4,
                        "chosen": true
                    }
                ]
            },
            "condition_filtering_pct": 100,
            "rows_for_plan": 1501,
            "cost_for_plan": 2103.4,
            "chosen": true
        }
    ]
}

{
    "reconsidering_access_paths_for_index_ordering": {
        "clause": "ORDER BY",
        "steps": [],
        "index_order_summary": {
            "table": "`push_tab`",
            "index_provides_order": true,
            "order_direction": "desc",
            "index": "idx_push_time",
            "plan_changed": false
        }
    },
    "refine_plan": [
        {
            "table": "`push_tab`",
            "pushed_index_condition": "(`push_tab`.`push_time` < 1668010460)",
            "table_condition_attached": "((`push_tab`.`is_delete` = 0) and (`push_tab`.`region` = 'us') and (`push_tab`.`plan_flag` in (0,1)))"
        }
    ]
}

这个优化步骤处于join_optimization阶段,可以看到在的considered_execution_plans里,mysql其实是正确选择了我们想走的索引。但是在 reconsidering_access_paths_for_index_ordering阶段,由于order by的原因却选择了idx_push_time这个不太理想的索引,导致最后重新制定了执行计划。所以下一步就需要看源码来查查看哪里出问题了。

4. 导致问题的mysql源码

经过一些资料的查找和源码的阅读发现,确实是在mysql优化时出现的问题,在mysql源码(5.7.40)的make_join_select函数里有这样一段逻辑:

/*
  We plan to scan (table/index/range scan).
  Check again if we should use an index. We can use an index if:
 
  1a) There is a condition that range optimizer can work on, and
  1b) There are non-constant conditions on one or more keys, and
  1c) Some of the non-constant fields may have been read
      already. This may be the case if this is not the first
      table in the join OR this is a subselect with
      non-constant conditions referring to an outer table
      (dependent subquery)
      or,
  2a) There are conditions only relying on constants
  2b) This is the first non-constant table
  2c) There is a limit of rows to read that is lower than
      the fanout for this table, predicate filters included
      (i.e., the estimated number of rows that will be
      produced for this table per row combination of
      previous tables)
  2d) The query is NOT run with FOUND_ROWS() (because in that
      case we have to scan through all rows to count them anyway)
*/
if (cond &&                                                // 1a
    (tab->keys() != tab->const_keys) &&                      // 1b
    (i > 0 ||                                              // 1c
     (join->select_lex->master_unit()->item &&
      cond->used_tables() & OUTER_REF_TABLE_BIT)))
  recheck_reason= NOT_FIRST_TABLE;
else if (!tab->const_keys.is_clear_all() &&                // 2a
         i == join->const_tables &&                        // 2b
         (join->unit->select_limit_cnt <
          (tab->position()->rows_fetched *
           tab->position()->filter_effect)) &&               // 2c
         !join->calc_found_rows)                             // 2d
  recheck_reason= LOW_LIMIT;

重点是倒数第二个if,就是2c那个条件,如果limit小于一定值就会让mysql启用limit优化。下面是判断是否走limit优化的代码:

/*
  We do a cost based search for an ordering index here. Do this
  only if prefer_ordering_index switch is on or an index is
  forced for order by
*/
if (recheck_reason != DONT_RECHECK &&
    (tab->table()->force_index_order ||
     thd->optimizer_switch_flag(
         OPTIMIZER_SWITCH_PREFER_ORDERING_INDEX)))
{
  int best_key= -1;
  ha_rows select_limit= join->unit->select_limit_cnt;
 
  /* Use index specified in FORCE INDEX FOR ORDER BY, if any. */
  if (tab->table()->force_index)
    usable_keys.intersect(tab->table()->keys_in_use_for_order_by);
 
  /* Do a cost based search on the indexes that give sort order */
  test_if_cheaper_ordering(tab, join->order, tab->table(),
                           usable_keys, -1, select_limit,
                           &best_key, &read_direction,
                           &select_limit);
  if (best_key < 0)
    recheck_reason= DONT_RECHECK; // No usable keys
  else
  {
    // Only usable_key is the best_key chosen
    usable_keys.clear_all();
    usable_keys.set_bit(best_key);
    interesting_order= (read_direction == -1 ? ORDER::ORDER_DESC :
                        ORDER::ORDER_ASC);
  }
}

上面recheck_reason是被赋值了的,我们没用强制索引,也没有打开OPTIMIZER_SWITCH_PREFER_ORDERING_INDEX这个开关(这个开关我下面会讲到),因此会走进test_if_cheaper_ordering这个函数的判断里。

test_if_cheaper_ordering这个函数会倾向排序时直接使用索引,所以会导致我们业务上的问题,函数里有这样一段注释如下:

/*
  We assume that each of the tested indexes is not correlated
  with ref_key. Thus, to select first N records we have to scan
  N/selectivity(ref_key) index entries. 
  selectivity(ref_key) = #scanned_records/#table_records =
  refkey_rows_estimate/table_records.
  In any case we can't select more than #table_records.
  N/(refkey_rows_estimate/table_records) > table_records
  <=> N > refkey_rows_estimate.
*/

首先假设被检查的索引同ref_key没有关系。其次假设数据是均匀分布的。如果数据是均匀分布的,那么通过排序索引访问前N行数据(order by limit N)需要扫描的行数为N*(table_records/distinct(ref_key))

这两个假设是估算通过排序索引来访问cost 的前提(但是现实生产中这两个假设在绝大多数场景中都是不成立的,所以就造成多数场景下索引选择错误)。 dev.mysql.com/worklog/tas…也有人报告了这个问题。

这里就完全解释的通线上出现的问题和做的实验了,在上面我是通过减少plan_flag=0的数量从而让mysql选择了正确的索引,但是其实只要改变limit的大小即可,只要limit够大就不会走这个奇葩的优化:

mysql> explain select * from push_tab where is_delete = 0 and push_time<1668010460 and region = 'us' and plan_flag in (0, 1) order by push_time desc limit 300 offset 0\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: push_tab
   partitions: NULL
         type: range
possible_keys: idx_push_time,idx_planflag_isdelete_region_pushtime
          key: idx_planflag_isdelete_region_pushtime
      key_len: 49
          ref: NULL
         rows: 1501
     filtered: 100.00
        Extra: Using index condition; Using filesort
1 row in set, 1 warning (0.01 sec)

5. 解决方案

  1. mysql在5.7.33版本通过加入开关(prefer_ordering_index)的方式来处理这个问题,我们线上的版本是5.7.29,数据库版本也不能随便升级,如果你可以升级版本则可以通过这种方式解决。
  2. 如果一次性取的数据不多的话可以把order by放在业务侧来做,即不使用order by语句,这样mysql是可以使用正确的索引的。
  3. 在sql语句中加入force index也可以避免这个问题。

6. 总结

可以看到,在mysql上同时使用order by和limit确实是有坑的,劣化索引选择的达成条件如下:

  1. 同时使用order by和limit
  2. order by的字段有现成索引可以用,且该索引与where期望使用的索引不一致
  3. limit的数量较少

在生产中我们需要注意这个问题,避免业务出现问题。

7. 扩展

  • mysql的test_if_cheaper_ordering函数做的比较简单,是在一次久远的版本中加入的,试图解决这个问题
  • 对于我遇到的这个问题的fix,mysql只是简单的做了个开关,并在5.7.33版本发布,相关讨论在这
  • 上面post的代码里跟limit判断时,用了这样的比较tab->position()->rows_fetched * tab->position()→filter_effect,这个filter_effect是mysql5.7新加入的,相关介绍在这 part1part2