MySQL online ddl 与 pt 并发执行导致更新丢失

vlambda
2022-05-10

MySQL online ddl 与 pt 并发执行导致更新丢失

1 引言

研发反馈SQL工单中的DDL显示执行，实际上没执行。

经查看，这个SQL工单中有三条SQL，包括一个create、一个alter、一个insert。

看现象，中间的alter没执行，前后的都执行了，现象看起来很诡异。

通过查询binlog确认这条DDL实际上执行了，而导致更新丢失的原因是在这条DDL开始执行之后，结束执行之前使用pt执行同一张表的DDL，online ddl 执行完成以后 pt 执行 drop table，进而导致更新丢失。

2 现象

2.1 查看字段

首先，登录数据库进行验证，显示 book_detail 数据表中当前确实没有 quota_occupy_process 字段。

mysql> use asn_newDatabase changedmysql> mysql> select quota_occupy_process from book_detail limit 1;ERROR 1054 (42S22): Unknown column 'quota_occupy_process' in 'field list'

2.2 查看执行日志

SQL工单执行日志中显示三条SQL均已执行。

EXECUTE START AT 2022-05-07 12:26:14--------------create table open_preempt_book_sup( id int unsigned NOT NULL AUTO_INCREMENT COMMENT '自增主键' primary key, sup_no varchar(255) not null comment '供应商编码', status tinyint not null comment '启用状态', create_user_id varchar(255) null comment '创建人', create_time datetime null comment '创建时间', update_user_id varchar(255) null comment '更新人', update_time datetime null comment '更新时间', yn tinyint default 1 not null comment '删除标志', ts timestamp NOT NULL DEFAULT '0000-00-00 00:00:00' ON UPDATE CURRENT_TIMESTAMP COMMENT '时间戳') comment '配额预占表'--------------
Query OK, 0 rows affected (0.01 sec)
--------------alter table book_detail add column quota_occupy_process tinyint default 1 null comment '占用配额方式(流程)，对应BookQuotaOccupyProcessEnum' after occupy_quota_flag--------------
Query OK, 0 rows affected (6 min 31.14 sec)Records: 0 Duplicates: 0 Warnings: 0
--------------insert into open_preempt_book_sup (sup_no, status, create_user_id, create_time, yn, ts)values ("*", "*", "*", now(), 1, now() )--------------
Query OK, 1 row affected (0.00 sec)
Byemysql: [Warning] Using a password on the command line interface can be insecure.EXECUTE DONE AT 2022-05-07 12:32:45

2.3 查看binlog

根据binlog可以最终判断这条DDL是否执行。

使用mysqlbinlog工具拉取binlog，指定当前操作时间对应的 binlog 文件名 mysql-bin.008012。

mysqlbinlog -R --raw --host=127.0.0.1 --user='admin' -p --port=3358 mysql-bin.008012

binlog文件如下所示。

[root@DB zhangkai321]# ll -h mysql-bin.008012 -rw-r----- 1 root root 517M May 7 14:18 mysql-bin.008012

继续使用mysqlbinlog分析binlog，生成SQL。

[root@DB zhangkai321]# mysqlbinlog --base64-output=DECODE-ROWS -v mysql-bin.008012 > 127.0.0.1.sql

SQL文件中查询要新增的字段名 quota_occupy_process，结果显示 12:32:45 时刻这条DDL执行成功并写入binlog。

[root@DB zhangkai321]# cat 127.0.0.1.sql.sql | grep -C 5 "quota_occupy_process"SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;/*!\C utf8 *//*!*/;SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;SET @@session.lc_time_names=0/*!*/;SET @@session.collation_database=DEFAULT/*!*/;alter table book_detail add column quota_occupy_process tinyint default 1 null comment '占用配额方式(流程)，对应BookQuotaOccupyProcessEnum' after occupy_quota_flag/*!*/;# at 493#220507 12:32:45 server id 1682448990 end_log_pos 541 CRC32 0xb913a91e GTID last_committed=0 sequence_number=0 rbr_only=noSET @@SESSION.GTID_NEXT= '2760f282-629c-11ea-ab35-fa163e99b3fe:364578288'/*!*/;# at 541

因此可以证明这条DDL实际上是执行了，但是为什么当前数据库中没有这个字段呢？

接下来分析原因。

3 分析

3.1 查询慢SQL

因此需要找到可能删除该字段的SQL，至少有两种方法，查询慢SQL或查询在 add column 后的全量binlog。

由于DDL是慢SQL的可能性较大，因此首先查询与 book_detail 数据表相关的慢SQL，这样用时会短一点。

经查询，2022-05-07 12:38:26 有执行 DROP TABLE IF EXISTS `asn_new`.`_book_detail_old`; 语句，而该语句是pt执行过程中的SQL，因此怀疑相近时间有使用pt执行同一张表的DDL。

3.2 工单系统

查询工单系统，显示同时执行了2个工单，一个原生加字段的和一个pt加索引的。

其中26分开始加字段，32分成功。27分开始pt加索引，pt生成新表的时候还没有这个字段，等pt执行完drop掉了老表，字段就白加了。

因此表明 online ddl 与 pt 并发执行可能导致更新丢失，下面通过复现进行验证。

3.3 pt执行日志

从慢SQL中可以看到有5条创建delete触发器的SQL，而insert与update触发器的创建应该很快，没有记录到慢SQL。

此外，这5条SQL的执行用时达到了60s，这是什么原因呢？

查询pt执行DDL的日志，从中可以看到 lock_wait_timeout=5，表明发生5次元数据锁等待。

而打印 lock_wait_timeout 的原因是pt命令中指定 --statistics 参数，因此将记录错误与重新尝试次数。

如下所示，日志中也可以看到表重命名的SQL。

RENAME TABLE `asn_new`.`book_detail` TO `asn_new`.`_book_detail_old`, `asn_new`.`_book_detail_new` TO `asn_new`.`book_detail`

因此，上文中慢SQL中记录到的删表SQL中的 _book_detail_old 表就是通过将原表 book_detail 表重命名而来的。

DROP TABLE IF EXISTS `asn_new`.`_book_detail_old`;

从日志中可以看到pt执行完成后的 book_detail 表就是在开始执行时创建的临时表 _book_detail_new，其中 occupy_quota_flag 字段后没有 quota_occupy_process 字段，而online ddl 执行的DDL操作中指定 add column quota_occupy_process after occupy_quota_flag，因此表明 online ddl 与 pt 并发执行导致更新丢失。

最后再整理下 online ddl 与 pt 执行的时间线，准备尝试进行复现。

online ddl	pt
26，开始执行
	27，开始执行
32，执行结束
	38，执行结束

4 复现

4.1 准备数据

test_zk 数据库的 t 数据表中行数100w。

mysql> select count(*) from t;+----------+| count(*) |+----------+| 1000000 |+----------+1 row in set (0.13 sec)

表结构如下所示。

mysql> show create table t \G*************************** 1. row *************************** Table: tCreate Table: CREATE TABLE `t` ( `id` int(10) NOT NULL AUTO_INCREMENT, `a` int(10) DEFAULT NULL COMMENT 'a', `name` varchar(20) DEFAULT NULL, `column` int(10) DEFAULT '0', `current_time` int(10) DEFAULT '0', PRIMARY KEY (`id`), KEY `idx_name` (`name`)) ENGINE=InnoDB AUTO_INCREMENT=1000001 DEFAULT CHARSET=utf81 row in set (0.00 sec)

4.2 online ddl

给表加字段。

mysql> alter table t add column b int(10) DEFAULT NULL COMMENT 'b';Query OK, 0 rows affected (5.82 sec)Records: 0 Duplicates: 0 Warnings: 0

执行期间查看数据目录，结果显示生成了DDL过程中临时文件。

实际上，由于 add column 是 in place 同时需要重建表。

[root@test test_zk]# pwd/export/zhangkai321/mysql/3341/data/test_zk[root@test test_zk]# [root@test test_zk]# ll -rth...-rw-r----- 1 mysql mysql 8.5K 5月 8 19:33 t.frm-rw-r----- 1 mysql mysql 88M 5月 8 19:33 t.ibd-rw-r----- 1 mysql mysql 8.6K 5月 8 19:33 #sql-4ae5_2d.frm-rw-r----- 1 mysql mysql 88M 5月 8 19:33 #sql-ib219-33873579.ibd

4.3 pt

首先将刚加的字段删除。

mysql> alter table t drop column b;Query OK, 0 rows affected (4.84 sec)Records: 0 Duplicates: 0 Warnings: 0

然后再次执行online ddl加字段操作。

mysql> alter table t add column b int(10) DEFAULT NULL COMMENT 'b';

在执行结束之前使用pt执行加索引操作。

[root@test zhangkai321]# pt-online-schema-change \-u admin -p 3341 -h 127.0.0.1 -P 3341 \--alter='ADD index idx_a(a);' --execute D=test_zk,t=t --charset=utf8 \--nocheck-replication-filters --max-load=Threads_running=50 \--critical-load=Threads_running=500,Threads_connected=800 \--recursion-method=hosts --max-lag=500 --check-interval=30 \--statistics --print --execute

online ddl 先执行结束，显示执行成功，返回与之前相同。

Query OK, 0 rows affected (5.56 sec)Records: 0 Duplicates: 0 Warnings: 0

pt 后执行结束，显示执行成功。

# Event Count# ====== =====# INSERT 17Successfully altered `test_zk`.`t`.

4.4 执行结果

查看表结构，结果显示 idx_a 索引是加上了，但是 b 字段并没有加上。

mysql> show create table t \G*************************** 1. row *************************** Table: tCreate Table: CREATE TABLE `t` ( `id` int(10) NOT NULL AUTO_INCREMENT, `a` int(10) DEFAULT NULL COMMENT 'a', `name` varchar(20) DEFAULT NULL, `column` int(10) DEFAULT '0', `current_time` int(10) DEFAULT '0', PRIMARY KEY (`id`), KEY `idx_name` (`name`), KEY `idx_a` (`a`)) ENGINE=InnoDB AUTO_INCREMENT=1000001 DEFAULT CHARSET=utf81 row in set (0.00 sec)

查看pt的执行日志，结果显示在开始执行时基于当前表结构创建的临时表 __t_new 中没有b字段，因此最终导致更新丢失。

CREATE TABLE `test_zk`.`__t_new` ( `id` int(10) NOT NULL AUTO_INCREMENT, `a` int(10) DEFAULT NULL COMMENT 'a', `name` varchar(20) DEFAULT NULL, `column` int(10) DEFAULT '0', `current_time` int(10) DEFAULT '0', PRIMARY KEY (`id`), KEY `idx_name` (`name`)) ENGINE=InnoDB AUTO_INCREMENT=1000001 DEFAULT CHARSET=utf8Created new table test_zk.__t_new OK.Altering new table...ALTER TABLE `test_zk`.`__t_new` ADD index idx_a(a);

下面分别回顾下 online ddl 与 pt 的执行流程，从理论上验证online ddl 与 pt 并发执行可能导致更新丢失。

5 原理

5.1 online ddl

5.1.1 简单流程

如下图所示是 online ddl 的执行流程。

建立一个临时文件，扫描表 A 主键的所有数据页；
用数据页中表 A 的记录生成 B+ 树，存储到临时文件中；
生成临时文件的过程中，将所有对 A 的操作记录在一个日志文件（row log）中，对应的是图中 state2 的状态；
临时文件生成后，将日志文件中的操作应用到临时文件，得到一个逻辑数据上与表 A 相同的数据文件，对应的就是图中 state3 的状态；
用临时文件替换表 A 的数据文件。

5.1.2 详细流程

1）Prepare 阶段

持有 EXCLUSIVE-MDL 锁，禁止DML操作，即禁止读写
根据DDL类型，确定执行方式（Copy、Online-rebuild、Online-no-rebuild）

add column 操作属于 Online-rebuild

创建新的 frm 和 ibd 临时文件（ibd临时文件仅rebuild类型需要）
分配 row_log 空间，用来记录 DDL Execute 阶段产生的DML操作（仅rebuild类型需要）

2）Execute 阶段

降级 EXCLUSIVE-MDL 锁，允许DML语句读写
扫描原表主键以及二级索引的所有数据页，生成B+树，存储到临时文件中
将 DDL Execute 阶段产生的DML操作记录到 row_log（仅rebuild类型需要）

3）Commit 阶段

升级到 EXCLUSIVE-MDL 锁，禁止DML语句读写
将 row_log 中记录的DML操作应用到临时文件，得到一个逻辑数据上与原表相同的数据文件（仅rebuild类型需要）
重命名 frm 和 idb 临时文件，替换原表，将原表文件删除
提交事务（刷事务的redo日志），变更完成
Prepare阶段和Commit阶段都禁止读写，主要是为了保证数据一致性。

注意：

在真正拷贝数据之前，MDL 锁从写锁降级为读锁是原因是避免阻塞增删改操作；
不直接获取MDL读锁的原因是禁止其他线程对这个表同时做DDL；
row_log 空间中仅记录 DDL Execute 阶段产生的DML操作，不记录DDL操作；
DDL创建临时文件，因此磁盘剩余空间必须大于表空间，否则将执行失败。这里磁盘的占用与binlog没关系，因为DDL对应statement类型的binlog，不会产生大量binlog；
MySQL 5.6版本以后支持 online ddl；
MySQL5.5版本以前实现中临时表tmp_table是在server层创建的，而在MySQL5.6版本以后实现中临时文件tmp_file是在InnoDB内部创建的，对于server层来说，没有将数据挪动到临时表中，是一个“原地”操作，也就是所谓的inplace。

5.2 pt

5.2.1 流程

pt 的详细执行流程如下所示：

Create new table，CREATE TABLE test_zk.__t_new
Alter new table，ALTER TABLE test_zk.__t_new ADD index idx_a(a);
Create triggers
Copy rows
Analyze new table
Swap tables，RENAME TABLE test_zk.t TO test_zk._t_old, test_zk.__t_new TO test_zk.t
Drop old table，DROP TABLE IF EXISTS test_zk._t_old
Drop triggers

5.2.2 重试次数

上文中提到一次 pt 执行过程中 lock_wait_timeout=5，发生5次元数据锁等待，具体是在创建触发器时重试了5次。

如下所示，是pt执行过程中默认尝试次数和尝试之间的等待时间（单位：秒）。

OPERATION	TRIES	WAIT
create_triggers	10	1
drop_triggers	10	1
copy_rows	10	0.25
swap_tables	10	1
update_foreign_keys	10	1
analyze_table	10	1

除此之外，也可以通过 --tries 参数执行重试次数。

5.3 并发执行

5.3.1 online ddl

一个表无法同时执行多个 online ddl，原因是DDL过程中需要获取MDL写锁，通过这种方式禁止其他线程对这个表同时做DDL。

下面进行测试验证。

一个session中新增字段b。

mysql> alter table t add column b int(10) DEFAULT NULL COMMENT 'b';

另一个session中新增字段c，阻塞等待。

mysql> alter table t add column c int(10) DEFAULT NULL COMMENT 'c';

最后一个session中查看连接，显示元数据锁等待。

mysql> SHOW PROCESSLIST;+----+-------+-----------------+---------+---------+------+---------------------------------+-------------------------------------------------------------+| Id | User | Host | db | Command | Time | State | Info |+----+-------+-----------------+---------+---------+------+---------------------------------+-------------------------------------------------------------+| 45 | admin | 127.0.0.1:53675 | test_zk | Query | 4 | altering table | alter table t add column b int(10) DEFAULT NULL COMMENT 'b' || 46 | admin | 127.0.0.1:55677 | test_zk | Query | 3 | Waiting for table metadata lock | alter table t add column c int(10) DEFAULT NULL COMMENT 'c' || 56 | admin | 127.0.0.1:41007 | NULL | Query | 0 | starting | SHOW PROCESSLIST |+----+-------+-----------------+---------+---------+------+---------------------------------+-------------------------------------------------------------+3 rows in set (0.00 sec)

查看元数据锁，owner_thread_id=71的连接在等待owner_thread_id=70的连接释放元数据锁。

mysql> select object_type,object_schema,object_name,lock_type,lock_duration,lock_status,owner_thread_id from performance_schema.metadata_locks;+-------------+--------------------+----------------+---------------------+---------------+-------------+-----------------+| object_type | object_schema | object_name | lock_type | lock_duration | lock_status | owner_thread_id |+-------------+--------------------+----------------+---------------------+---------------+-------------+-----------------+| GLOBAL | NULL | NULL | INTENTION_EXCLUSIVE | STATEMENT | GRANTED | 70 || SCHEMA | test_zk | NULL | INTENTION_EXCLUSIVE | TRANSACTION | GRANTED | 70 || TABLE | test_zk | t | SHARED_UPGRADABLE | TRANSACTION | GRANTED | 70 || GLOBAL | NULL | NULL | INTENTION_EXCLUSIVE | STATEMENT | GRANTED | 71 || SCHEMA | test_zk | NULL | INTENTION_EXCLUSIVE | TRANSACTION | GRANTED | 71 || TABLE | test_zk | t | SHARED_UPGRADABLE | TRANSACTION | PENDING | 71 || TABLE | performance_schema | metadata_locks | SHARED_READ | TRANSACTION | GRANTED | 81 |+-------------+--------------------+----------------+---------------------+---------------+-------------+-----------------+7 rows in set (0.00 sec)

第一个session执行结束。

Query OK, 0 rows affected (5.18 sec)Records: 0 Duplicates: 0 Warnings: 0

第二个session执行结束，执行用时明显较多，原因是发生过锁等待。

Query OK, 0 rows affected (9.64 sec)Records: 0 Duplicates: 0 Warnings: 0

实际上，多个 online ddl 将依次执行，第一条执行结束以后第二条才可以开始执行。

5.3.2 pt

一个表无法同时执行的多个pt，原因是pt执行DDL过程中需要给表创建触发器，通过这种方式禁止其他线程对这个表同时做DDL。

下面进行测试验证。

首先执行第一条，使用 pt 给 t 表新增索引 idx_b。

[root@test zhangkai321]# pt-online-schema-change \> -u admin -p 3341 -h 127.0.0.1 -P 3341 \> --alter='ADD index idx_b(b);' --execute D=test_zk,t=t --charset=utf8 \> --nocheck-replication-filters --max-load=Threads_running=50 \> --critical-load=Threads_running=500,Threads_connected=800 \> --recursion-method=hosts --max-lag=500 --check-interval=30 --statistics \> --print --executeAltering `test_zk`.`t`...Creating new table......

然后执行第二条，使用 pt 给 t 表新增索引 idx_c。

[root@test ~]# pt-online-schema-change \> -u admin -p 3341 -h 127.0.0.1 -P 3341 \> --alter='ADD index idx_c(c);' --execute D=test_zk,t=t --charset=utf8 \> --nocheck-replication-filters --max-load=Threads_running=50 \> --critical-load=Threads_running=500,Threads_connected=800 \> --recursion-method=hosts --max-lag=500 --check-interval=30 --statistics \> --print --execute

第一条执行成功。

2022-05-08T22:49:13 Dropped triggers OK.# Event Count# ====== =====# INSERT 17Successfully altered `test_zk`.`t`.

第二条执行失败，报错该表已经有触发器，因此无法执行。

The table `test_zk`.`t` has triggers but --preserve-triggers was not specified.Please read the documentation for --preserve-triggers.

实际上，多个pt 将依次执行，同样第一条执行结束以后第二条才可以开始执行。

5.3.3 online ddl + pt

综上可以发现 online ddl 与 pt 分别从实现中禁止其他线程对这个表同时做DDL，但是如果 online ddl 与 pt 同时执行，由于实现原理不同，无法限制。

当 online ddl 与 pt 并发执行时，可能导致更新丢失，需要从操作上去规避。

online ddl 与 pt 执行的相同点是都会在开始执行时获取到当前表结构，更新完成以后交换表。

6 结论

SQL工单中有三条SQL，包括一个create、一个alter、一个insert。

看现象，中间的alter没执行，前后的都执行了。

经验证，这条DDL实际上执行了，但是在这条DDL开始执行之后，结束执行之前使用pt执行同一张表的DDL，online ddl 执行完成以后 pt 执行 drop table，进而导致更新丢失。

online ddl 与 pt 执行的相同点是都会在开始执行时获取到当前表结构，更新完成以后交换表。

online ddl 与 pt 分别都不支持并发执行，其中前者持有MDL锁，后者创建触发器。

但是如果 online ddl 与 pt 同时执行，由于实现原理不同，无法限制。

而当 online ddl 与 pt 并发执行时，可能导致更新丢失，需要从操作上去规避。

7 小技巧

定位SQL，至少有两种方法，查询慢SQL或查询binlog，建议使用前者；
并发执行会引入额外的复杂度，学习的过程中需要关注。

8 待办

online ddl 详细流程（copy & inplace）
pt 详细流程

参考教程

Online DDL Operations

https://dev.mysql.com/doc/refman/5.7/en/innodb-online-ddl-operations.html#online-ddl-column-operations

Online DDL Performance and Concurrency

https://dev.mysql.com/doc/refman/5.7/en/innodb-online-ddl-performance.html

关于mysql在线ddl的原理和实验-干货！

https://www.modb.pro/db/56128

为什么表数据删掉一半，表文件大小不变？

https://time.geekbang.org/column/article/72388

技术分享 | Online DDL 工具 pt-osc

https://segmentfault.com/a/1190000024481446

vlambda博客
学习文章列表