使用 pt-osc 工具增加字段时的不当处理导致了一次故障

| dbtan

故事是这样的...

小宝同学在使用 pt-osc 给一个表 A 增加字段，Copying 数据时，异常中断了，字段没有增加成功。（此时，还没有故障）

小宝同学也知道 pt-osc 失败后，需要「清理现场」（删除生成的临时表和触发器）。

但不知道为何只是删除了临时表，而没有删除3个触发器...

这就引发了这次故障，无法对此表 A 进行 insert/update/delete 操作，报错提示 _A_new 不存在。

让我们模拟一下故事中的场景

1. 准备一个测试表 test_log

root@[10.141.8.203].[dbtan] 14:42:19> select count(*) from test_log;
+----------+
| count(*) |
+----------+
| 26045360 |
+----------+
1 row in set (5.14 sec)

root@[10.141.8.203].[dbtan] 14:42:31> select max(log_id) from test_log;
+-------------+
| max(log_id) |
+-------------+
|    26129680 |
+-------------+
1 row in set (0.05 sec)

root@[10.141.8.203].[dbtan] 14:42:50> show create table test_log \G
*************************** 1. row ***************************
       Table: test_log
Create Table: CREATE TABLE `test_log` (
  `log_id` int(11) NOT NULL AUTO_INCREMENT COMMENT '主键ID',
  `abcd_id` int(11) NOT NULL,
  `state` varchar(3) NOT NULL,
  `create_time` datetime NOT NULL,
  PRIMARY KEY (`log_id`)
) ENGINE=InnoDB AUTO_INCREMENT=26171841 DEFAULT CHARSET=utf8mb4
1 row in set (0.00 sec)

2. 准备为表 test_log 增加一个字段 column1

我们先看使用 --print --dry-run 查看下 pt-osc 的操作步骤是这样的：

  • 创建一个和要执行 alter 操作的表一样的新的空表 _test_log_new 表结构(是alter之前的结构)
  • 在新表 _test_log_new 执行 alter table 语句（速度应该很快，此时还是空表）
  • 在原表 test_log 中创建触发器3个触发器分别对应 insert/update/delete操作
  • 以一定块大小从原表 test_log 拷贝数据到临时表 _test_log_new，拷贝过程中通过原表上的触发器在原表进行的写操作都会更新到新建的临时表
  • 交换表名 swap_tables (_test_log_new <-->test_log): rename 原表test_log 到 _test_log_old 表中，再把临时表 _test_log_new rename为原表test_log
  • 如果有参考该表的外键，根据 alter-foreign-keys-method 参数的值，检测外键相关的表，做相应设置的处理
  • 默认最后将旧原表 _test_log_old 删除。
[root@test-178: ~]# pt-online-schema-change --no-version-check --user=root --password='123456' --host=localhost --chunk-size-limit=1000000 --charset=utf8 P=3306,D=dbtan,t=test_log --alter="ADD COLUMN column1 tinyint(4) DEFAULT NULL" --print --dry-run
Operation, tries, wait:
  analyze_table, 10, 1
  copy_rows, 10, 0.25
  create_triggers, 10, 1
  drop_triggers, 10, 1
  swap_tables, 10, 1
  update_foreign_keys, 10, 1
Starting a dry run.  `dbtan`.`test_log` will not be altered.  Specify --execute instead of --dry-run to alter the table.
Creating new table...
CREATE TABLE `dbtan`.`_test_log_new` (
  `log_id` int(11) NOT NULL AUTO_INCREMENT COMMENT '主键ID',
  `abcd_id` int(11) NOT NULL,
  `state` varchar(3) NOT NULL,
  `create_time` datetime NOT NULL,
  PRIMARY KEY (`log_id`)
) ENGINE=InnoDB AUTO_INCREMENT=26171841 DEFAULT CHARSET=utf8mb4
Created new table dbtan._test_log_new OK.
Altering new table...
ALTER TABLE `dbtan`.`_test_log_new` ADD COLUMN column1 tinyint(4) DEFAULT NULL
Altered `dbtan`.`_test_log_new` OK.
Not creating triggers because this is a dry run.
Not copying rows because this is a dry run.
INSERT LOW_PRIORITY IGNORE INTO `dbtan`.`_test_log_new` (`log_id`, `abcd_id`, `state`, `create_time`) SELECT `log_id`, `abcd_id`, `state`, `create_time` FROM `dbtan`.`test_log` LOCK IN SHARE MODE /*pt-online-schema-change 4525 copy table*/
Not swapping tables because this is a dry run.
Not dropping old table because this is a dry run.
Not dropping triggers because this is a dry run.
DROP TRIGGER IF EXISTS `dbtan`.`pt_osc_dbtan_test_log_del`
DROP TRIGGER IF EXISTS `dbtan`.`pt_osc_dbtan_test_log_upd`
DROP TRIGGER IF EXISTS `dbtan`.`pt_osc_dbtan_test_log_ins`
2019-06-26T20:11:06 Dropping new table...
DROP TABLE IF EXISTS `dbtan`.`_test_log_new`;
2019-06-26T20:11:06 Dropped new table OK.
Dry run complete.  `dbtan`.`test_log` was not altered.
[root@test-178: ~]#

3. 模拟 pt-osc 过程中异常中断。

我们在使用 pt-osc 为 test_log 增加一个字段 column1 过程中，手工 control+c 中断。模拟「异常中断」。

[root@test-178: ~]# pt-online-schema-change --no-version-check --user=root --password='123456' --host=localhost --chunk-size-limit=1000000 --charset=utf8 P=3306,D=dbtan,t=test_log --alter="ADD COLUMN column1 tinyint(4) DEFAULT NULL" --print --execute
No slaves found.  See --recursion-method if host test-178 has slaves.
Not checking slave lag because no slaves were found and --check-slave-lag was not specified.
Operation, tries, wait:
  analyze_table, 10, 1
  copy_rows, 10, 0.25
  create_triggers, 10, 1
  drop_triggers, 10, 1
  swap_tables, 10, 1
  update_foreign_keys, 10, 1
Altering `dbtan`.`test_log`...
Creating new table...
CREATE TABLE `dbtan`.`_test_log_new` (
  `log_id` int(11) NOT NULL AUTO_INCREMENT COMMENT '主键ID',
  `abcd_id` int(11) NOT NULL,
  `state` varchar(3) NOT NULL,
  `create_time` datetime NOT NULL,
  PRIMARY KEY (`log_id`)
) ENGINE=InnoDB AUTO_INCREMENT=26171841 DEFAULT CHARSET=utf8mb4
Created new table dbtan._test_log_new OK.
Altering new table...
ALTER TABLE `dbtan`.`_test_log_new` ADD COLUMN column1 tinyint(4) DEFAULT NULL
Altered `dbtan`.`_test_log_new` OK.
2019-06-26T21:07:53 Creating triggers...
2019-06-26T21:07:53 Created triggers OK.
2019-06-26T21:07:53 Copying approximately 25059595 rows...
INSERT LOW_PRIORITY IGNORE INTO `dbtan`.`_test_log_new` (`log_id`, `abcd_id`, `state`, `create_time`) SELECT `log_id`, `abcd_id`, `state`, `create_time` FROM `dbtan`.`test_log` LOCK IN SHARE MODE /*pt-online-schema-change 8681 copy table*/
^C^C^C^C^C^C
^C^C^C^C^C^C
^C^C^C^C^C^C^C
# Exiting on SIGINT.
Not dropping triggers because the tool was interrupted.  To drop the triggers, execute:
DROP TRIGGER IF EXISTS `dbtan`.`pt_osc_dbtan_test_log_del`
DROP TRIGGER IF EXISTS `dbtan`.`pt_osc_dbtan_test_log_upd`
DROP TRIGGER IF EXISTS `dbtan`.`pt_osc_dbtan_test_log_ins`
Not dropping the new table `dbtan`.`_test_log_new` because the tool was interrupted.  To drop the new table, execute:
DROP TABLE IF EXISTS `dbtan`.`_test_log_new`;
`dbtan`.`test_log` was not altered.
[root@test-178: ~]#

手工 control+c 模拟「异常中断」后，我们看到输出显示“由于工具被中断了，没能删除触发器和新表 _test_log_new”

4. 查看新表和触发器

root@[10.141.8.203].[dbtan] 21:08:53> show tables;
+-----------------+
| Tables_in_dbtan |
+-----------------+
| _test_log_new   |
| test_log        |
+-----------------+
2 rows in set (0.00 sec)

root@[10.141.8.203].[dbtan] 21:08:54> show triggers \G
*************************** 1. row ***************************
             Trigger: pt_osc_dbtan_test_log_ins
               Event: INSERT
               Table: test_log
           Statement: REPLACE INTO `dbtan`.`_test_log_new` (`log_id`, `abcd_id`, `state`, `create_time`) VALUES (NEW.`log_id`, NEW.`abcd_id`, NEW.`state`, NEW.`create_time`)
              Timing: AFTER
             Created: NULL
            sql_mode: NO_AUTO_VALUE_ON_ZERO,STRICT_TRANS_TABLES,NO_ENGINE_SUBSTITUTION
             Definer: root@localhost
character_set_client: utf8
collation_connection: utf8_general_ci
  Database Collation: utf8mb4_general_ci
*************************** 2. row ***************************
             Trigger: pt_osc_dbtan_test_log_upd
               Event: UPDATE
               Table: test_log
           Statement: BEGIN DELETE IGNORE FROM `dbtan`.`_test_log_new` WHERE !(OLD.`log_id` <=> NEW.`log_id`) AND `dbtan`.`_test_log_new`.`log_id` <=> OLD.`log_id`;REPLACE INTO `dbtan`.`_test_log_new` (`log_id`, `abcd_id`, `state`, `create_time`) VALUES (NEW.`log_id`, NEW.`abcd_id`, NEW.`state`, NEW.`create_time`);END
              Timing: AFTER
             Created: NULL
            sql_mode: NO_AUTO_VALUE_ON_ZERO,STRICT_TRANS_TABLES,NO_ENGINE_SUBSTITUTION
             Definer: root@localhost
character_set_client: utf8
collation_connection: utf8_general_ci
  Database Collation: utf8mb4_general_ci
*************************** 3. row ***************************
             Trigger: pt_osc_dbtan_test_log_del
               Event: DELETE
               Table: test_log
           Statement: DELETE IGNORE FROM `dbtan`.`_test_log_new` WHERE `dbtan`.`_test_log_new`.`log_id` <=> OLD.`log_id`
              Timing: AFTER
             Created: NULL
            sql_mode: NO_AUTO_VALUE_ON_ZERO,STRICT_TRANS_TABLES,NO_ENGINE_SUBSTITUTION
             Definer: root@localhost
character_set_client: utf8
collation_connection: utf8_general_ci
  Database Collation: utf8mb4_general_ci
3 rows in set (0.00 sec)

root@[10.141.8.203].[dbtan] 21:08:58> 
root@[10.141.8.203].[dbtan] 16:43:08> show create table test_log \G
*************************** 1. row ***************************
       Table: test_log
Create Table: CREATE TABLE `test_log` (
  `log_id` int(11) NOT NULL AUTO_INCREMENT COMMENT '主键ID',
  `abcd_id` int(11) NOT NULL,
  `state` varchar(3) NOT NULL,
  `create_time` datetime NOT NULL,
  PRIMARY KEY (`log_id`)
) ENGINE=InnoDB AUTO_INCREMENT=26171841 DEFAULT CHARSET=utf8mb4
1 row in set (0.05 sec)

root@[10.141.8.203].[dbtan] 16:43:43> show create table _test_log_new \G
*************************** 1. row ***************************
       Table: _test_log_new
Create Table: CREATE TABLE `_test_log_new` (
  `log_id` int(11) NOT NULL AUTO_INCREMENT COMMENT '主键ID',
  `abcd_id` int(11) NOT NULL,
  `state` varchar(3) NOT NULL,
  `create_time` datetime NOT NULL,
  `column1` tinyint(4) DEFAULT NULL,
  PRIMARY KEY (`log_id`)
) ENGINE=InnoDB AUTO_INCREMENT=26171841 DEFAULT CHARSET=utf8mb4
1 row in set (0.00 sec)

root@[10.141.8.203].[dbtan] 16:43:57> select count(*) from test_log;
+----------+
| count(*) |
+----------+
| 26045360 |
+----------+
1 row in set (5.16 sec)

root@[10.141.8.203].[dbtan] 16:44:35> select count(*) from _test_log_new;
+----------+
| count(*) |
+----------+
| 26045360 |
+----------+
1 row in set (5.23 sec)

root@[10.141.8.203].[dbtan] 16:44:50> 
root@[10.141.8.203].[dbtan] 17:47:52> select max(log_id) from test_log;
+-------------+
| max(log_id) |
+-------------+
|    26129680 |
+-------------+
1 row in set (0.00 sec)

root@[10.141.8.203].[dbtan] 17:50:18> select max(log_id) from _test_log_new;
+-------------+
| max(log_id) |
+-------------+
|    26129680 |
+-------------+
1 row in set (0.00 sec)

root@[10.141.8.203].[dbtan] 17:50:27>

5. 模拟故障。只删除新表 _test_log_new，测试“增/改/删”操作。

5.1. 不删除新表的情况

在不删除新表 _test_log_new 时，对原表 test_log 进行 insert/update/delete 操作。

操作正常，触发器会更新新表 _test_log_new。

root@[10.141.8.203].[dbtan] 18:25:15> insert into test_log(abcd_id, state, create_time) values(66668888, 'abc', now());                             
Query OK, 1 row affected (0.02 sec)

root@[10.141.8.203].[dbtan] 18:25:44> select max(log_id) from test_log ;
+-------------+
| max(log_id) |
+-------------+
|    26171841 |
+-------------+
1 row in set (0.00 sec)

root@[10.141.8.203].[dbtan] 18:26:28> select * from test_log where log_id = 26171841;
+----------+----------+-------+---------------------+
| log_id   | abcd_id  | state | create_time         |
+----------+----------+-------+---------------------+
| 26171841 | 66668888 | abc   | 2019-06-27 18:25:44 |
+----------+----------+-------+---------------------+
1 row in set (0.00 sec)

root@[10.141.8.203].[dbtan] 18:26:47> select * from _test_log_new where log_id = 26171841;
+----------+----------+-------+---------------------+---------+
| log_id   | abcd_id  | state | create_time         | column1 |
+----------+----------+-------+---------------------+---------+
| 26171841 | 66668888 | abc   | 2019-06-27 18:25:44 |    NULL |
+----------+----------+-------+---------------------+---------+
1 row in set (0.00 sec)
5.2. 删除新表的情况

只删除新表 _test_log_new 后，对原表 test_log 进行 insert/update/delete 操作。

因为 AFTER trigger 触发器的存在，会更新新表 _test_log_new，但此时新表 _test_log_new 已被删除了。

所以，报错提示 _test_log_new 不存在。

操作过程是：

  1. 开启事务。
  2. 操作原表 test_log
  3. 触发 AFTER trigger 触发器。操作新表 _test_log_new 时报错（表不存在）
  4. 回滚对原表 test_log 的操作。
  5. 关闭事务。
root@[10.141.8.203].[dbtan] 18:34:00> drop table _test_log_new;
Query OK, 0 rows affected (1.02 sec)

root@[10.141.8.203].[dbtan] 18:34:02> insert into test_log(abcd_id, state, create_time) values(66669999, 'ABC', now()); 
ERROR 1146 (42S02): Table 'dbtan._test_log_new' doesn't exist
root@[10.141.8.203].[dbtan] 18:34:08> 
root@[10.141.8.203].[dbtan] 18:34:15> update test_log set abcd_id = 66669999 where abcd_id = 66668888;
ERROR 1146 (42S02): Table 'dbtan._test_log_new' doesn't exist
root@[10.141.8.203].[dbtan] 18:34:33> delete from test_log where abcd_id = 66668888;
ERROR 1146 (42S02): Table 'dbtan._test_log_new' doesn't exist
root@[10.141.8.203].[dbtan] 18:34:58>

6. 删除3个触发器，再进行 insert/update/delete 操作恢复正常。

root@[10.141.8.203].[dbtan] 19:11:35> DROP TRIGGER IF EXISTS `dbtan`.`pt_osc_dbtan_test_log_del`;
Query OK, 0 rows affected (0.01 sec)

root@[10.141.8.203].[dbtan] 19:11:36> DROP TRIGGER IF EXISTS `dbtan`.`pt_osc_dbtan_test_log_upd`;
Query OK, 0 rows affected (0.02 sec)

root@[10.141.8.203].[dbtan] 19:11:42> DROP TRIGGER IF EXISTS `dbtan`.`pt_osc_dbtan_test_log_ins`;
Query OK, 0 rows affected (0.00 sec)

root@[10.141.8.203].[dbtan] 19:11:46> 
root@[10.141.8.203].[dbtan] 19:18:44> insert into test_log(abcd_id, state, create_time) values(66669999, 'ABC', now()); 
Query OK, 1 row affected (0.00 sec)

root@[10.141.8.203].[dbtan] 19:18:45> update test_log set abcd_id = 66668888 where abcd_id = 66669999;
Query OK, 1 row affected (16.81 sec)
Rows matched: 1  Changed: 1  Warnings: 0

root@[10.141.8.203].[dbtan] 19:19:06> delete from test_log where abcd_id = 66668888;
Query OK, 1 row affected (17.12 sec)

使用 pt-osc 与 原生 5.6 online ddl 相比，如何选择

  • online ddl 在必须 copy table 时成本较高，不宜采用
  • pt-osc 工具在存在触发器时，不适用
  • 修改索引、外键、列名时，优先采用 online ddl，并指定 ALGORITHM=INPLACE
  • 其它情况使用 pt-osc，虽然存在 copy data
  • pt-osc 比 online ddl 要慢一倍左右，因为它是根据负载调整的
  • 无论哪种方式都选择的业务低峰期执行
  • 特殊情况需要利用主从特性，先alter从库，主备切换，再改原主库

Choosing the right DDL option

参考： https://www.percona.com/blog/2014/11/18/avoiding-mysql-alter-table-downtime/

总结一下

  • 这次故障由于在使用 pt-osc 为表增加字段这类 DDL 操作时，发生中断的后续操作处理不当，导致无法对原表 DML 操作的严重事故。

  • 通过测试，我们知道 pt-osc 的操作原理：
    1. 创建一个和要执行 alter 操作的表一样的新的空表 _test_log_new 表结构(是alter之前的结构)
    2. 在新表 _test_log_new 执行 alter table 语句（速度应该很快，此时还是空表）
    3. 在原表 test_log 中创建触发器3个触发器分别对应 insert/update/delete操作
    4. 以一定块大小从原表 test_log 拷贝数据到临时表 _test_log_new，拷贝过程中通过原表上的触发器在原表进行的写操作都会更新到新建的临时表
    5. 交换表名 swap_tables (_test_log_new <-->test_log): rename 原表test_log 到 _test_log_old 表中，再把临时表 _test_log_new rename为原表test_log
    6. 如果有参考该表的外键，根据 alter-foreign-keys-method 参数的值，检测外键相关的表，做相应设置的处理
    7. 默认最后将旧原表 _test_log_old 删除。

归根到底，就是通过3个 AFTER trigger 同步增量数据变化的。

所以，在使用 pt-osc 操作过程中发生中断，「清理现场」：首先要在做的就是「切断」原表与新表之间的联系（删除3个trigger），清理（删除）新表次之。

-- The End --