MySQL增加索引导致主从同步延时更大的重现与分析

Posted 2021-05-02 BOSSClouds

生产上有一套mysql库，一主二从，使用MHA做高可用。在主库大进行大量删除操作之后，从库应用缓慢，主从延时很大。经查，进行大量删除的表既无主键、也无其他索引。在删除语句的筛选字段上增加索引之后，发现从库应用缓慢的现象并没有消失，反而更加严重。最后在表上增加主键，问题才得以解决。本文将该生产问题复现到测试环境，通过无索引批量删除、有索引批量删除以及有主键批量删除三次测试，分析出表中有无主键是影响从库同步性能的关键因素。

问题

业务对MySQL数据库中的一张表进行大量删除操作，造成从库同步的延时过大。之后业务对表中删除操作相关字段进行增加索引的操作，但是并没有效果。下面在测试环境复现场景并且分析。

配置信息

1.主机信息

IP               主机名      CPU 内存
xxx.xxx.32.127    k8s-node1   8C  16G
xxx.xxx.32.141    k8s-node2   8C  16G
xxx.xxx.32.144    k8s-node3   8C  16G
# CPU信息
vendor_id    : GenuineIntel
cpu family   : 6
model        : 94
model name   : Intel Core Processor (Skylake, IBRS)
stepping     : 3
microcode    : 0x1
cpu MHz      : 2194.842
cache size   : 16384 KB

2.MySQL配置信息

port = 3307
transaction_isolation = READ-COMMITTED
innodb_buffer_pool_size=100M
innodb_log_file_size = 50M
innodb_log_files_in_group = 7
innodb_undo_tablespaces = 3
binlog_format = ROW
sync_binlog = 1
long_query_log = 0.1

xxx.xxx.32.127 为主库
xxx.xxx.32.141 为从库1
xxx.xxx.32.144 为从库2

主库配置

+-------------------------------------------+------------+
| Variable_name                             | Value      |
+-------------------------------------------+------------+
| rpl_semi_sync_master_enabled              | ON         |
| rpl_semi_sync_master_wait_for_slave_count | 1          |
| rpl_semi_sync_master_wait_no_slave        | ON         |
| rpl_semi_sync_master_wait_point           | AFTER_SYNC | 
| rpl_semi_sync_slave_enabled               | ON         |
+-------------------------------------------+------------+

从库配置

+-------------------------------------------+------------+
| Variable_name                             | Value      |
+-------------------------------------------+------------+
| rpl_semi_sync_master_enabled              | OFF        |
+-------------------------------------------+------------+

测试准备

1.创建数据库

mysql> create database bossdb;

2.创建用户

mysql> grant all privileges on bossdb.* to 'boss'@'localhost' identified by 'bosscloud'; 

3.创建表

mysql> use bossdb;
mysql> create table `t1` (
    `tcol01` varchar(10) NOT NULL,
    `tcol02` varchar(10) NOT NULL,
      `tcol03` datetime NOT NULL,
      `tcol04` varchar(20) DEFAULT NULL,
      `tcol05` char(1) DEFAULT NULL,
      `tcol06` varchar(20) DEFAULT NULL,
      `tcol` varchar(20) NOT NULL,
      `tcol07` int(11) DEFAULT '0',
      `tcol08` varchar(20) DEFAULT NULL,
      `tcol09` varchar(100) DEFAULT NULL,
      `tcol10` varchar(255) DEFAULT NULL,
      `tcol11` varchar(255) DEFAULT NULL,
      `tcol12` int(10) DEFAULT NULL,
      `tcol13` int(10) DEFAULT '0',
      `tcol21` date DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 ROW_FORMAT=DYNAMIC;

重点：无主键、无索引

[mysqlcat@k8s-node1 ~]$ ./mysql_random_data_load bossdb t1 200000 -hxxx.xxx.32.127 -P3307 -uboss -pbosscloud
INFO[2020-04-20T16:02:56+08:00] Starting                                     
 1m7s [====================================================================] 100%
INFO[2020-04-20T16:04:05+08:00] 100000 rows inserted   

十万行数据用了1m7s，因为数据库的buffer_pool_size和onlinelog都配置的比较小，这个效果还是可以的。
这句命令执行了两遍，总共插入了20万条数据。
考虑到t1表中的tcol是记录的日期，格式如下‘20200421’，这也是后文的关键字段，mysql_random_data_load随机生成的varchar并不符合要求。我们使用update语句将datetime字段的年月日赋值给该字段。避免不必要的主从同步，在update的时候关闭了sql_log_bin参数。

xxx.xxx.32.127

mysql> set sql_log_bin=0;
mysql> update bossdb.t1 set tcol=date_format(tcol03,'%Y%m%d');
mysql> set sql_log_bin=1;

xxx.xxx.32.141/144

mysql> set sql_log_bin=0;
mysql> set global super_read_only=0;
mysql> update bossdb.t1 set tcol=date_format(tcol03,'%Y%m%d');
mysql> set global super_read_only=1;
mysql> set sql_log_bin=1;

xxx.xxx.32.127

mysql> select count(*) from bossdb.t1 where tcol<'20200401';
+----------+
| count(*) |
+----------+
|   189158 |
+----------+
1 row in set (1.18 sec)
mysql> explain delete from bossdb.t1 where tcol<'20200401';
+----+-------------+-------+------------+------+---------------+------+---------+------+--------+----------+-------------+
| id | select_type | table | partitions | type | possible_keys | key  | key_len | ref  | rows   | filtered | Extra       |
+----+-------------+-------+------------+------+---------------+------+---------+------+--------+----------+-------------+
|  1 | DELETE      | t1    | NULL       | ALL  | NULL          | NULL | NULL    | NULL | 197242 |   100.00 | Using where |
+----+-------------+-------+------------+------+---------------+------+---------+------+--------+----------+-------------+

下面这句话是接下来的重点，此处执行计划为全表扫描。

delete from bossdb.t1 where tcol<'20200401';

5.撰写脚本
在/tmp/在，写两个脚本，如下。master status以及slave status的数据
5.1 gather_master_status.sh
放在xxx.xxx.32.127，用来记录主库的master status数据

!/bin/bash
while [ true ]; do
/bin/sleep 1
/bin/date >>/tmp/gather_master_status.txt
/mysql/app/bin/mysql -s -e "show master status\G;"  >>/tmp/gather_master_status.txt
echo ''>>/tmp/gather_master_status.txt
echo ''>>/tmp/gather_master_status.txt
done

5.2 gather_slave_status.sh
放在xxx.xxx.32.141/144上，用来记录从库的slave status数据

!/bin/bash
while [ true ]; do
/bin/sleep 1
/bin/date >>/tmp/gather_slave_status.txt
/mysql/app/bin/mysql  -s -e "show slave status\G;"  >>/tmp/gather_slave_status.txt
echo ''>>/tmp/gather_slave_status.txt
echo ''>>/tmp/gather_slave_status.txt
done

5.3 显示Second Behind Master脚本
在xxx.xxx.32.141/144的命令行执行，显示何时降为0.

[mysqlcat@k8s-node1 ~]$ while [ true ]; do sleep 2;date;a=`mysql -e "show slave status\G;"|grep "Seconds_Behind_Master"`;echo $a;b=`echo $a|awk -F ': ' '{print $2}'`;if [ $b == 0 ];then echo 'Finished';break;else echo 'Not yet';fi;done;

6.备份数据

[mysqlcat@k8s-node1 ~]$ mysqldump --set-gtid-purged=OFF --databases bossdb |gzip>/mysqlcat/backup/bossdb.sql.gz

测试1 无索引下批量删除

1.执行脚本
xxx.xxx.32.127/141/144

[mysqlcat@k8s-node1 ~]$ nohup sh /tmp/gather*status.sh 2>&1 >/dev/null &

xxx.xxx.32.141/144

[mysqlcat@k8s-node1 ~]$ while [ true ]; do sleep 2;date;a=`mysql -e "show slave status\G;"|grep "Seconds_Behind_Master"`;echo $a;b=`echo $a|awk -F ': ' '{print $2}'`;if [ $b == 0 ];then echo 'Finished';break;else echo 'Not yet';fi;done;

2.删除

mysql> delete from bossdb.t1 where tcol<'20200401';

3.查看慢日志

# Time: 2020-04-20T17:07:32.885274+08:00
# User@Host: root[root] @ localhost []  Id:  5586
# Query_time: 4.996057  Lock_time: 0.000140 Rows_sent: 0  Rows_examined: 200000
SET timestamp=1587373652;
delete from bossdb.t1 where tcol<'20200401';

4.等待Seconds_Behind_Master归零
xxx.xxx.32.141

Mon Apr 20 17:07:32 CST 2020
 Second Behind Master 5
Not yet
Mon Apr 20 17:14:27 CST 2020  
 Second Behind Master 0
Finished

耗时415s
xxx.xxx.32.144

Mon Apr 20 17:07:32 CST 2020
 Second Behind Master 5
Not yet
Mon Apr 20 17:14:09 CST 2020
 Second Behind Master 0
Finished

耗时397s
5.停止脚本的执行
xxx.xxx.32.127/141/144

[mysqlcat@k8s-node1 ~]$ ps -ef|grep gather_*_status|grep -v grep|awk -F ' ' '{print $2}'|xargs kill

6.使用mysqlbinlog分析binlog

[mysqlcat@k8s-node1 ~]$mysqlbinlog --start-datetime='2020-04-20 17:07:27' --stop-datetime='2020-04-20 17:07:31' -vv

binlog 部分如下

# at 353150914
#200420 17:07:27 server id 127  end_log_pos 353150981 CRC32 0x9eabf598     Rows_query
# delete from bossdb.t1 where tcol<'20200401'
# at 353150981
#200420 17:07:27 server id 127  end_log_pos 353151064 CRC32 0x747fcc33     Table_map: `bossdb`.`t1` mapped to number 118
# at 353151064
#200420 17:07:27 server id 127  end_log_pos 353159207 CRC32 0xc7c827e6     Delete_rows: table id 118

 748833 ### DELETE FROM `bossdb`.`t1`
 748834 ### WHERE
 748835 ###   @1='Ann' /* VARSTRING(40) meta=40 nullable=0 is_null=0 */
 748836 ###   @2='Gerald' /* VARSTRING(40) meta=40 nullable=0 is_null=0 */
 748837 ###   @3='2019-11-01 19:07:41' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
 748838 ###   @4='Jesse Lewis' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
 748839 ###   @5='G' /* STRING(4) meta=65028 nullable=1 is_null=0 */
 748840 ###   @6='Timothy Little' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
 748841 ###   @7='20191101' /* VARSTRING(80) meta=80 nullable=0 is_null=0 */
 748842 ###   @8=2038042080 /* INT meta=0 nullable=1 is_null=0 */
 748843 ###   @9='Marie Welch' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
 748844 ###   @10='fuga qui omnis molestiae veritatis ut optio recusandae.' /* VARSTRING(400) meta=400 nullable=1 is_null=0 */
 748845 ###   @11='expedita in quia reiciendis facilis qui.' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */
 748846 ###   @12='laboriosam et aut modi qui non.' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */
 748847 ###   @13=627801321 /* INT meta=0 nullable=1 is_null=0 */
 748848 ###   @14=51425520 /* INT meta=0 nullable=1 is_null=0 */
 748849 ###   @15='2020:04:20' /* DATE meta=0 nullable=1 is_null=0 */
3964502 ### DELETE FROM `bossdb`.`t1`
3964503 ### WHERE
3964504 ###   @1='Pamela' /* VARSTRING(40) meta=40 nullable=0 is_null=0 */
3964505 ###   @2='Harry' /* VARSTRING(40) meta=40 nullable=0 is_null=0 */
3964506 ###   @3='2019-09-03 08:08:56' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
3964507 ###   @4='Jeremy Fisher' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
3964508 ###   @5='C' /* STRING(4) meta=65028 nullable=1 is_null=0 */
3964509 ###   @6='Mr. Dr. Matthew Fost' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
3964510 ###   @7='20190903' /* VARSTRING(80) meta=80 nullable=0 is_null=0 */
3964511 ###   @8=666660140 /* INT meta=0 nullable=1 is_null=0 */
3964512 ###   @9='Mrs. Ms. Miss Kelly ' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
3964513 ###   @10='nostrum temporibus atque.' /* VARSTRING(400) meta=400 nullable=1 is_null=0 */
3964514 ###   @11='voluptatem ut voluptas sint quo autem aliquid iure.' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */
3964515 ###   @12='in commodi dolor doloremque rerum nobis.' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */
3964516 ###   @13=156647923 /* INT meta=0 nullable=1 is_null=0 */
3964517 ###   @14=764931703 /* INT meta=0 nullable=1 is_null=0 */
3964518 ###   @15='2020:04:20' /* DATE meta=0 nullable=1 is_null=0 */
3964519 # at 395096777

可以看到，虽然主库只是执行了一句delete操作，但是因为我们设定的是基于行的binlog格式，所以binlog中，会记下匹配到的189158条delete操作，再将这些delete操作传输给从库，显然是非常惊人的。
7.时间线

17:07:28 开始执行 delete from bossdb.t1 where tcol<'20200401';
17:07:31 binlog写完
17:07:32 主库执行完成
17:07:32 从库开始有second behind master不为0
17:14:09 从库2的second_behind_master 0
17:14:27 从库1的second_behind_master 0

主库执行5秒钟，主从同步用了500s左右。

测试2 增加索引 批量删除

1.恢复数据
xxx.xxx.32.127

[mysqlcat@k8s-node1 ~]$ mysql</mysqlcat/backup/bossdb.sql

2.给tcol字段增加索引
xxx.xxx.32.127

mysql> alter table t1 add index idx_tcol(`tcol`);
mysql> show create table t1;
| t1    | CREATE TABLE `t1` (
  `tcol01` varchar(10) NOT NULL,
  `tcol02` varchar(10) NOT NULL,
  `tcol03` datetime NOT NULL,
  `tcol04` varchar(20) DEFAULT NULL,
  `tcol05` char(1) DEFAULT NULL,
  `tcol06` varchar(20) DEFAULT NULL,
  `tcol` varchar(20) NOT NULL,
  `tcol07` int(11) DEFAULT '0',
  `tcol08` varchar(20) DEFAULT NULL,
  `tcol09` varchar(100) DEFAULT NULL,
  `tcol10` varchar(255) DEFAULT NULL,
  `tcol11` varchar(255) DEFAULT NULL,
  `tcol12` int(10) DEFAULT NULL,
  `tcol13` int(10) DEFAULT '0',
  `tcol21` date DEFAULT NULL,
  KEY `idx_tcol` (`tcol`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 ROW_FORMAT=DYNAMIC |

(重复操作不再赘述，见测试1)
3.删除

mysql> explain delete from bossdb.t1 where tcol<'20200401';
+----+-------------+-------+------------+------+---------------+------+---------+------+--------+----------+-------------+
| id | select_type | table | partitions | type | possible_keys | key  | key_len | ref  | rows   | filtered | Extra       |
+----+-------------+-------+------------+------+---------------+------+---------+------+--------+----------+-------------+
|  1 | DELETE      | t1    | NULL       | ALL  | idx_tcol    | NULL | NULL    | NULL | 187534 |   100.00 | Using where |
+----+-------------+-------+------------+------+---------------+------+---------+------+--------+----------+-------------+

mysql> delete from bossdb.t1 where tcol<'20200401';
Query OK, 189158 rows affected (6.74 sec)

4.时间线

11:24:10  开始执行 delete from bossdb.t1 where tcol<'20200401';
11:24:17 binlog写完
11:24:17 主库执行完成
11:24:17 从库开始有second behind master不为0
12:28:13 从库2的second_behind_master 0
12:37:23 从库1的second_behind_master 0

主库执行6.7秒钟，主从同步用了3600s左右。

期中分析

问题：为什么t1表加了索引，但是效果为什么比原来没有还要差很多呢？

不知道大家有没有关注到测试2中的delete执行计划，possible_keys中有idx_tcol，但是key中没有，也就是说delete操作根本就没有走索引，在进行了比较之后，MySQL仍然认为走全表扫描是cost更小的方式。

但是有了索引，也就是多了一次比较。而且索引也是需要空间的，增加索引也增加了数据库的大小。主库执行满了1s多，可以理解。但是从库的同步时间几乎被慢了10倍，这是为什么呢？

因为从库的执行时一行行执行的，类似这种

DELETE FROM `bossdb`.`t1`
WHERE
  @1='Ann' /* VARSTRING(40) meta=40 nullable=0 is_null=0 */
  @2='Gerald' /* VARSTRING(40) meta=40 nullable=0 is_null=0 */
  @3='2019-11-01 19:07:41' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
  @4='Jesse Lewis' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
  @5='G' /* STRING(4) meta=65028 nullable=1 is_null=0 */
  @6='Timothy Little' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
  @7='20191101' /* VARSTRING(80) meta=80 nullable=0 is_null=0 */
  @8=2038042080 /* INT meta=0 nullable=1 is_null=0 */
  @9='Marie Welch' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
  @10='fuga qui omnis molestiae veritatis ut optio recusandae.' /* VARSTRING(400) llable=1 is_null=0 */
  @11='expedita in quia reiciendis facilis qui.' /* VARSTRING(1020) meta=1020 is_null=0 */
  @12='laboriosam et aut modi qui non.' /* VARSTRING(1020) meta=1020 nullable=1 /
  @13=627801321 /* INT meta=0 nullable=1 is_null=0 */
  @14=51425520 /* INT meta=0 nullable=1 is_null=0 */
  @15='2020:04:20' /* DATE meta=0 nullable=1 is_null=0 */

我们改写了一下，并且看他的执行计划

mysql> explain DELETE FROM `bossdb`.`t1`
WHERE
  tcol01='Ann' and
  tcol02='Gerald' and
  tcol03='2019-11-01 19:07:41' and
  tcol04='Jesse Lewis' and
  tcol05='G' and
  tcol06='Timothy Little' and
  tcol ='20191101' and
  tcol07=2038042080 and
  tcol08='Marie Welch' and
  tcol09=='fuga qui omnis molestiae veritatis ut optio recusandae.' and
  tcol10=='expedita in quia reiciendis facilis qui.' and
  tcol11=='laboriosam et aut modi qui non.' and
  tcol12==627801321 and
  tcol13==51425520 and
  tcol21=='2020:04:20';
+----+-------------+-------+------------+------+---------------+------+---------+------+--------+----------+-------------+
| id | select_type | table | partitions | type | possible_keys | key  | key_len | ref  | rows   | filtered | Extra       |
+----+-------------+-------+------------+------+---------------+------+---------+------+--------+----------+-------------+
|  1 | DELETE      | t1    | NULL       | range  | idx_tcol    | idx_tcol | 82    | const | 1 |   100.00 | Using where |
+----+-------------+-------+------------+------+---------------+------+---------+------+--------+----------+-------------+

MySQL其实选择走了索引，这很可能就是执行非常慢的原因。而且大量的删除操作，还会带来索引维护的开销增大，十分不可取。
最后，我们试试增加主键。

测试3 增加主键 批量删除

1.删除表
xxx.xxx.32.127

mysql> truncate bossdb.t1;

2.增加主键

mysql> alter table bossdb.t1 add (id int);
mysql> alter table bossdb.t1 add constraint pk primary key(id);

3.重新造数据
xxx.xxx.32.127

[mysqlcat@k8s-node1 ~]$ ./mysql_random_data_load bossdb t1 200000 
INFO[2020-04-21T22:35:50+08:00] Starting 
 3m5s [====================================================================] 100%
INFO[2020-04-21T22:38:57+08:00] 200000 rows inserted 

4.更新tcol字段
详细见测试1和2

5.删除

mysql> select count(*) from bossdb.t1 where tcol<'20200401';
+----------+
| count(*) |
+----------+
|   188535 |
+----------+
1 row in set (2.52 sec)

mysql> explain delete from bossdb.t1 where tcol<'20200401';
+----+-------------+-------+------------+------+---------------+------+---------+------+--------+----------+-------------+
| id | select_type | table | partitions | type | possible_keys | key  | key_len | ref  | rows   | filtered | Extra       |
+----+-------------+-------+------------+------+---------------+------+---------+------+--------+----------+-------------+
|  1 | DELETE      | t1    | NULL       | ALL  | NULL          | NULL | NULL    | NULL | 199988 |   100.00 | Using where |
+----+-------------+-------+------------+------+---------------+------+---------+------+--------+----------+-------------+
1 row in set (0.00 sec)

mysql> delete from bossdb.t1 where tcol<'20200401';

6.查看慢日志以及等待Second_Behinds_Master归零

# Time: 2020-04-21T22:42:04.524712+08:00
# User@Host: root[root] @ localhost []  Id:  9795
# Query_time: 13.810188  Lock_time: 0.000130 Rows_sent: 0  Rows_examined: 200000
SET timestamp=1587480124;
delete from bossdb.t1 where tcol<'20200401';

Tue Apr 21 22:42:16 CST 2020
Seconds_Behind_Master: 26
False
Tue Apr 21 22:42:18 CST 2020
Seconds_Behind_Master: 28
False
Tue Apr 21 22:42:20 CST 2020
Seconds_Behind_Master: 30
False
Tue Apr 21 22:42:22 CST 2020
Seconds_Behind_Master: 0
True

7.时间线

22:41:51 开始执行 delete from bossdb.t1 where tcol<'20200401';
22:42:04 binlog写完
22:42:04 主库执行完成
22:42:04 从库开始有second behind master不为0
22:42:22 从库2的second_behind_master 0
22:42:22 从库1的second_behind_master 0

主库执行13秒钟，主从同步用了18s左右。

期末分析

有主键的表主从同步快的十分明显，证明删除操作走主键是最有效的。主库执行时间长因为是因为维护主键的开销，可以忽略。
还有个好方法可以增加主键，不需要迁移数据，直接加自增非空列。

mysql> alter table bossdb.t1 add column `id` int not null auto_increment primary key first;

因此得出结论，MySQL在基于行复制的主从同步模式下，建议所有表有主键。对于批量的删除操作，特别有效。