1.pt-osc工具
1.1.pt-osc简介
pt-osc是pt-online-schema-change的简写，pt-online-schema-change是percona-toolkit工具包中用于在线变更DDL的工具
1.2.pt-osc原理
1.3.pt-toolkit安装
# yum install perl-ExtUtils-CBuilder perl-ExtUtils-MakeMaker cpan
# yum load-transaction /tmp/yum_save_tx.2022-12-24.23-11.fKEVvh.yumtx
# unzip percona-toolkit-3.5.0.zip
# cd /root/percona-toolkit-3.5.0
# perl Makefile.PL && make -j 4 &7 make install -j 4
2.pt-osc等待Waiting for table metadata lock锁模拟
2.1.创建一个未提交insert语句
获取meatadata lock ，锁类型是SHARED_READ
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> insert low_priority ignore into t select 11,'L';
Query OK, 1 row affected (0.00 sec)
Records: 1 Duplicates: 0 Warnings: 0
mysql>
2.2.使用pt-osc工具创建索引
pt-osc工具执行创建索引过程需要等待metadata lock，并且在10min9.136s后Lock wait timeout exceeded后退出，为什么需要等待10多分钟才会超时退出？
# time pt-online-schema-change --host=172.20.23.4 --port=3306 -utest -ptest D=test9988,t=t,A=utf8 --alter-foreign-keys-method=auto --recursion-method=none --no-check-replication-filter --execute --alter="add index idx_t(name)"
No slaves found. See --recursion-method if host zCloud-Proxy-Ex 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
Child tables:
`test9988`.`t_sub` (approx. 4 rows)
Will automatically choose the method to update foreign keys.
Altering `test9988`.`t`...
Creating new table...
Created new table test9988._t_new OK.
Altering new table...
Altered `test9988`.`_t_new` OK.
2022-12-25T17:41:54 Creating triggers...
Error creating triggers: 2022-12-25T17:52:03 DBD::mysql::db do failed: Lock wait timeout exceeded; try restarting transaction [for Statement "CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END "] at /usr/local/bin/pt-online-schema-change line 11481.
2022-12-25T17:52:03 Dropping triggers...
2022-12-25T17:52:03 Dropped triggers OK.
2022-12-25T17:52:03 Dropping new table...
2022-12-25T17:52:03 Dropped new table OK.
`test9988`.`t` was not altered.
(in cleanup) 2022-12-25T17:52:03 DBD::mysql::db do failed: Lock wait timeout exceeded; try restarting transaction [for Statement "CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END "] at /usr/local/bin/pt-online-schema-change line 11481.
2022-12-25T17:52:03 Dropping triggers...
2022-12-25T17:52:03 Dropped triggers OK.
`test9988`.`t` was not altered.
real 10min9.136s
user 0m0.179s
sys 0m0.030s
2.3.查看创建过程中的processlist信息
pt-osc执行过程一直在Waiting for table metadata lock 锁，并且可以看到在等待60s后释放一次锁，然后继续Waiting for table metadata lock锁，重试了多次60s后报错Lock wait timeout exceeded退出执行，具体需要重试多少次，为什么是每次是等待60s呢？
mysql> select * from information_schema.processlist where command<>'Sleep' and INFO is not null and user='test'\G
*************************** 1. row ***************************
ID: 174
USER: test
HOST: 172.20.23.4:29613
DB: test9988
COMMAND: Query
TIME: 59
STATE: Waiting for table metadata lock
INFO: CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END
1 row in set (0.00 sec)
mysql> select * from information_schema.processlist where command<>'Sleep' and INFO is not null and user='test'\G
Empty set (0.00 sec)
mysql> select * from information_schema.processlist where command<>'Sleep' and INFO is not null and user='test'\G
*************************** 1. row ***************************
ID: 174
USER: test
HOST: 172.20.23.4:29613
DB: test9988
COMMAND: Query
TIME: 0
STATE: Waiting for table metadata lock
INFO: CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END
1 row in set (0.00 sec)
mysql> select * from information_schema.processlist where command<>'Sleep' and INFO is not null and user='test'\G
*************************** 1. row ***************************
ID: 174
USER: test
HOST: 172.20.23.4:29613
DB: test9988
COMMAND: Query
TIME: 1
STATE: Waiting for table metadata lock
INFO: CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END
1 row in set (0.00 sec)
mysql> select * from information_schema.processlist where command<>'Sleep' and INFO is not null and user='test'\G
*************************** 1. row ***************************
ID: 174
USER: test
HOST: 172.20.23.4:29613
DB: test9988
COMMAND: Query
TIME: 3
STATE: Waiting for table metadata lock
INFO: CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END
1 row in set (0.00 sec)
2.4.查看生产的general log日志
从日志中可以看到SET SESSION lock_wait_timeout=60被设置了，由此可知等待metadata lock 60秒后就会超时；但是为什么可以重试10次、并且为什么每次重试间隔时间是61秒呢？
2022-12-25T17:41:54.573026+08:00 174 Connect [email protected] on test9988 using TCP/IP
2022-12-25T17:41:54.574196+08:00 174 Query /*!40101 SET NAMES "utf8"*/
2022-12-25T17:41:54.574835+08:00 174 Query SHOW VARIABLES LIKE 'innodb\_lock_wait_timeout'
2022-12-25T17:41:54.577014+08:00 174 Query SET SESSION innodb_lock_wait_timeout=1
2022-12-25T17:41:54.577236+08:00 174 Query SHOW VARIABLES LIKE 'lock\_wait_timeout'
2022-12-25T17:41:54.578985+08:00 174 Query SET SESSION lock_wait_timeout=60
2022-12-25T17:41:54.579153+08:00 174 Query SHOW VARIABLES LIKE 'wait\_timeout'
2022-12-25T17:41:54.580731+08:00 174 Query SET SESSION wait_timeout=10000
2022-12-25T17:41:54.580927+08:00 174 Query SELECT @@SQL_MODE
2022-12-25T17:41:54.581074+08:00 174 Query SET @@SQL_QUOTE_SHOW_CREATE = 1/*!40101, @@SQL_MODE='NO_AUTO_VALUE_ON_ZERO,ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION'*/
2022-12-25T17:41:54.581239+08:00 174 Query SELECT VERSION()
2022-12-25T17:41:54.581386+08:00 174 Query SHOW VARIABLES LIKE 'character_set_server'
2022-12-25T17:41:54.582990+08:00 174 Query SET NAMES 'utf8mb4'
2022-12-25T17:41:54.583161+08:00 174 Query SELECT @@server_id /*!50038 , @@hostname*/
2022-12-25T17:41:54.584349+08:00 175 Connect [email protected] on test9988 using TCP/IP
2022-12-25T17:41:54.584802+08:00 175 Query /*!40101 SET NAMES "utf8"*/
2022-12-25T17:41:54.585094+08:00 175 Query SHOW VARIABLES LIKE 'innodb\_lock_wait_timeout'
2022-12-25T17:41:54.586953+08:00 175 Query SET SESSION innodb_lock_wait_timeout=1
2022-12-25T17:41:54.587120+08:00 175 Query SHOW VARIABLES LIKE 'lock\_wait_timeout'
2022-12-25T17:41:54.588833+08:00 175 Query SET SESSION lock_wait_timeout=60
2022-12-25T17:41:54.589015+08:00 175 Query SHOW VARIABLES LIKE 'wait\_timeout'
2022-12-25T17:41:54.590572+08:00 175 Query SET SESSION wait_timeout=10000
2022-12-25T17:41:54.590763+08:00 175 Query SELECT @@SQL_MODE
2022-12-25T17:41:54.590899+08:00 175 Query SET @@SQL_QUOTE_SHOW_CREATE = 1/*!40101, @@SQL_MODE='NO_AUTO_VALUE_ON_ZERO,ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION'*/
2022-12-25T17:41:54.591091+08:00 175 Query SELECT VERSION()
2022-12-25T17:41:54.591244+08:00 175 Query SHOW VARIABLES LIKE 'character_set_server'
2022-12-25T17:41:54.592835+08:00 175 Query SET NAMES 'utf8mb4'
2022-12-25T17:41:54.593027+08:00 175 Query SELECT @@server_id /*!50038 , @@hostname*/
2022-12-25T17:41:54.593295+08:00 174 Query SHOW VARIABLES LIKE 'wsrep_on'
2022-12-25T17:41:54.595069+08:00 174 Query SHOW VARIABLES LIKE 'version%'
2022-12-25T17:41:54.596937+08:00 174 Query SHOW ENGINES
2022-12-25T17:41:54.597405+08:00 174 Query SHOW VARIABLES LIKE 'innodb_version'
2022-12-25T17:41:54.599557+08:00 174 Query SHOW VARIABLES LIKE 'innodb_stats_persistent'
2022-12-25T17:41:54.601348+08:00 174 Query SHOW GLOBAL STATUS LIKE 'Threads_running'
2022-12-25T17:41:54.602964+08:00 174 Query SHOW GLOBAL STATUS LIKE 'Threads_running'
2022-12-25T17:41:54.603910+08:00 174 Query SELECT CONCAT(@@hostname, @@port)
2022-12-25T17:41:54.604355+08:00 174 Query SHOW TABLES FROM `test9988` LIKE 't'
2022-12-25T17:41:54.605663+08:00 174 Query SELECT VERSION()
2022-12-25T17:41:54.605888+08:00 174 Query SHOW TRIGGERS FROM `test9988` LIKE 't'
2022-12-25T17:41:54.606822+08:00 174 Query /*!40101 SET @OLD_SQL_MODE := @@SQL_MODE, @@SQL_MODE := '', @OLD_QUOTE := @@SQL_QUOTE_SHOW_CREATE, @@SQL_QUOTE_SHOW_CREATE := 1 */
2022-12-25T17:41:54.606972+08:00 174 Query USE `test9988`
2022-12-25T17:41:54.607125+08:00 174 Query SHOW CREATE TABLE `test9988`.`t`
2022-12-25T17:41:54.607621+08:00 174 Query /*!40101 SET @@SQL_MODE := @OLD_SQL_MODE, @@SQL_QUOTE_SHOW_CREATE := @OLD_QUOTE */
2022-12-25T17:41:54.608067+08:00 174 Query EXPLAIN SELECT * FROM `test9988`.`t` WHERE 1=1
2022-12-25T17:41:54.608640+08:00 174 Query SELECT table_schema, table_name FROM information_schema.key_column_usage WHERE referenced_table_schema='test9988' AND referenced_table_name='t'
2022-12-25T17:41:54.612094+08:00 174 Query EXPLAIN SELECT * FROM `test9988`.`t_sub` WHERE 1=1
2022-12-25T17:41:54.612547+08:00 174 Query SHOW VARIABLES LIKE 'version%'
2022-12-25T17:41:54.614432+08:00 174 Query SHOW ENGINES
2022-12-25T17:41:54.614886+08:00 174 Query SHOW VARIABLES LIKE 'innodb_version'
2022-12-25T17:41:54.616925+08:00 174 Query SELECT table_schema, table_name FROM information_schema.key_column_usage WHERE referenced_table_schema='test9988' AND referenced_table_name='t'
2022-12-25T17:41:54.620420+08:00 174 Query EXPLAIN SELECT * FROM `test9988`.`t_sub` WHERE 1=1
2022-12-25T17:41:54.621340+08:00 174 Query SHOW VARIABLES LIKE 'wsrep_on'
2022-12-25T17:41:54.623137+08:00 174 Query /*!40101 SET @OLD_SQL_MODE := @@SQL_MODE, @@SQL_MODE := '', @OLD_QUOTE := @@SQL_QUOTE_SHOW_CREATE, @@SQL_QUOTE_SHOW_CREATE := 1 */
2022-12-25T17:41:54.623296+08:00 174 Query USE `test9988`
2022-12-25T17:41:54.623455+08:00 174 Query SHOW CREATE TABLE `test9988`.`t`
2022-12-25T17:41:54.623858+08:00 174 Query /*!40101 SET @@SQL_MODE := @OLD_SQL_MODE, @@SQL_QUOTE_SHOW_CREATE := @OLD_QUOTE */
2022-12-25T17:41:54.624136+08:00 174 Query CREATE TABLE `test9988`.`_t_new` (
`id` int NOT NULL,
`name` varchar(20) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL,
PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_general_ci
2022-12-25T17:41:54.641180+08:00 174 Query ALTER TABLE `test9988`.`_t_new` add index idx_t(name)
2022-12-25T17:41:54.654810+08:00 174 Query /*!40101 SET @OLD_SQL_MODE := @@SQL_MODE, @@SQL_MODE := '', @OLD_QUOTE := @@SQL_QUOTE_SHOW_CREATE, @@SQL_QUOTE_SHOW_CREATE := 1 */
2022-12-25T17:41:54.655073+08:00 174 Query USE `test9988`
2022-12-25T17:41:54.655270+08:00 174 Query SHOW CREATE TABLE `test9988`.`_t_new`
2022-12-25T17:41:54.655794+08:00 174 Query /*!40101 SET @@SQL_MODE := @OLD_SQL_MODE, @@SQL_QUOTE_SHOW_CREATE := @OLD_QUOTE */
2022-12-25T17:41:54.656796+08:00 174 Query SELECT TRIGGER_SCHEMA, TRIGGER_NAME, DEFINER, ACTION_STATEMENT, SQL_MODE, CHARACTER_SET_CLIENT, COLLATION_CONNECTION, EVENT_MANIPULATION, ACTION_TIMING FROM INFORMATION_SCHEMA.TRIGGERS WHERE EVENT_MANIPULATION = 'DELETE' AND ACTION_TIMING = 'AFTER' AND TRIGGER_SCHEMA = 'test9988' AND EVENT_OBJECT_TABLE = 't'
2022-12-25T17:41:54.658070+08:00 174 Query SELECT TRIGGER_SCHEMA, TRIGGER_NAME, DEFINER, ACTION_STATEMENT, SQL_MODE, CHARACTER_SET_CLIENT, COLLATION_CONNECTION, EVENT_MANIPULATION, ACTION_TIMING FROM INFORMATION_SCHEMA.TRIGGERS WHERE EVENT_MANIPULATION = 'UPDATE' AND ACTION_TIMING = 'AFTER' AND TRIGGER_SCHEMA = 'test9988' AND EVENT_OBJECT_TABLE = 't'
2022-12-25T17:41:54.658862+08:00 174 Query SELECT TRIGGER_SCHEMA, TRIGGER_NAME, DEFINER, ACTION_STATEMENT, SQL_MODE, CHARACTER_SET_CLIENT, COLLATION_CONNECTION, EVENT_MANIPULATION, ACTION_TIMING FROM INFORMATION_SCHEMA.TRIGGERS WHERE EVENT_MANIPULATION = 'INSERT' AND ACTION_TIMING = 'AFTER' AND TRIGGER_SCHEMA = 'test9988' AND EVENT_OBJECT_TABLE = 't'
2022-12-25T17:41:54.659630+08:00 174 Query SELECT TRIGGER_SCHEMA, TRIGGER_NAME, DEFINER, ACTION_STATEMENT, SQL_MODE, CHARACTER_SET_CLIENT, COLLATION_CONNECTION, EVENT_MANIPULATION, ACTION_TIMING FROM INFORMATION_SCHEMA.TRIGGERS WHERE EVENT_MANIPULATION = 'DELETE' AND ACTION_TIMING = 'BEFORE' AND TRIGGER_SCHEMA = 'test9988' AND EVENT_OBJECT_TABLE = 't'
2022-12-25T17:41:54.660359+08:00 174 Query SELECT TRIGGER_SCHEMA, TRIGGER_NAME, DEFINER, ACTION_STATEMENT, SQL_MODE, CHARACTER_SET_CLIENT, COLLATION_CONNECTION, EVENT_MANIPULATION, ACTION_TIMING FROM INFORMATION_SCHEMA.TRIGGERS WHERE EVENT_MANIPULATION = 'UPDATE' AND ACTION_TIMING = 'BEFORE' AND TRIGGER_SCHEMA = 'test9988' AND EVENT_OBJECT_TABLE = 't'
2022-12-25T17:41:54.661063+08:00 174 Query SELECT TRIGGER_SCHEMA, TRIGGER_NAME, DEFINER, ACTION_STATEMENT, SQL_MODE, CHARACTER_SET_CLIENT, COLLATION_CONNECTION, EVENT_MANIPULATION, ACTION_TIMING FROM INFORMATION_SCHEMA.TRIGGERS WHERE EVENT_MANIPULATION = 'INSERT' AND ACTION_TIMING = 'BEFORE' AND TRIGGER_SCHEMA = 'test9988' AND EVENT_OBJECT_TABLE = 't'
2022-12-25T17:41:54.661873+08:00 174 Query CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END
2022-12-25T17:42:55.663366+08:00 174 Query CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END
2022-12-25T17:43:56.664487+08:00 174 Query CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END
2022-12-25T17:44:57.665834+08:00 174 Query CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END
2022-12-25T17:45:58.671920+08:00 174 Query CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END
2022-12-25T17:46:59.677982+08:00 174 Query CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END
2022-12-25T17:48:00.679605+08:00 174 Query CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END
2022-12-25T17:49:01.683615+08:00 174 Query CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END
2022-12-25T17:50:02.684720+08:00 174 Query CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END
2022-12-25T17:51:03.685696+08:00 174 Query CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END
2022-12-25T17:52:03.687438+08:00 174 Query SHOW TABLES FROM `test9988` LIKE '\_t\_new'
2022-12-25T17:52:03.690557+08:00 174 Query DROP TABLE IF EXISTS `test9988`.`_t_new`
2022-12-25T17:52:03.702208+08:00 175 Quit
2022-12-25T17:52:03.702979+08:00 174 Query SHOW TABLES FROM `test9988` LIKE '\_t\_new'
2022-12-25T17:52:03.709141+08:00 174 Quit
2.5.查看pt-osc执行的命令
可以看到输出中有一项 create_triggers, 10, 1 ;这个10的意思tries 10次，可以知道需要尝试10次了；1的意思是wait 1秒，由此可知每次重试需要等待1秒，这1秒时间内其他session可以进行正常的DML操作，因为这时候create triggers不在等待metadata lock EXCLUSIVE锁。因为lock_wait_timeout被设置为60秒，索引每次create_triggers失败后，需要间隔61（60+1）秒后才会再次重试
# pt-online-schema-change --host=172.20.23.4 --port=3306 -utest -ptest D=test9988,t=t,A=utf8 --alter-foreign-keys-method=auto --recursion-method=none --no-check-replication-filter --execute --alter="add index idx_t(name)"
pt-online-schema-change --host=172.20.23.4 --port=3306 -utest -ptest D=test9988,t=t,A=utf8 --alter-foreign-keys-method=auto --recursion-method=none --no-check-replication-filter --execute --alter="add index idx_t(name)"
No slaves found. See --recursion-method if host zCloud-Proxy-Ex 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
--alter-foreign-keys-method=auto auto
表示在drop_swrap和rebuild_constraints 两种方式中进行选择
如果使用 drop_swrap 的时候，会先删除旧表 然后将 新表重命名为原表名
(原因是在rename的时候原来的外键约束名称也会更改，这里不通过名称交换再删除就是为了防止原来的约束名称改变)；如果使用 rebuild_constraints 的方式，则是通过交换表名的方式进行的，只不过是再重新构建了外键约束，通过改表名，外键约束对应的表名也被更改。
--no-check-replication-filters 表示不需要检查 Master 配置里是否指定了 Filter。 默认会检查，如果配置了 Filter，如 replicate_do_db,replicate-wild-ignore-table,binlog_ignore_db 等，在从库checksum就与遇到表不存在而报错退出，所以官方默认是yes（--check-replication-filters）但我们实际在检测中时指定--databases=，所以就不存在这个问题，干脆不检测。
--recursion-method=none 标识不去查找从，即使从有延迟
2.5.修改tries次数和lock_wait_timeout时间
修改create_triggers的尝试次数为1次，并且等待时间还是1秒；lock_wait_timeout时间为10秒
# pt-online-schema-change --host=172.20.23.4 -P3306 -utest -ptest D=test9988,t=t,A=utf8 --alter-foreign-keys-method=auto --recursion-method=none --no-check-replication-filter --execute --alter="add index idx_t(name)" --tries create_triggers:1:1 --set-vars="lock_wait_timeout=10"
2.5.1.执行时间降低到0m10.364s
# time pt-online-schema-change --host=172.20.23.4 -P3306 -utest -ptest D=test9988,t=t,A=utf8 --alter-foreign-keys-method=auto --recursion-method=none --no-check-replication-filter --execute --alter="add index idx_t(name)" --tries create_triggers:1:1 --set-vars="lock_wait_timeout=10"
No slaves found. See --recursion-method if host zCloud-Proxy-Ex 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, 1, 1
drop_triggers, 10, 1
swap_tables, 10, 1
update_foreign_keys, 10, 1
Child tables:
`test9988`.`t_sub` (approx. 4 rows)
Will automatically choose the method to update foreign keys.
Altering `test9988`.`t`...
Creating new table...
Created new table test9988._t_new OK.
Altering new table...
Altered `test9988`.`_t_new` OK.
2022-12-25T19:02:44 Creating triggers...
Error creating triggers: 2022-12-25T19:02:54 DBD::mysql::db do failed: Lock wait timeout exceeded; try restarting transaction [for Statement "CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END "] at /usr/local/bin/pt-online-schema-change line 11481.
2022-12-25T19:02:54 Dropping triggers...
2022-12-25T19:02:54 Dropped triggers OK.
2022-12-25T19:02:54 Dropping new table...
2022-12-25T19:02:54 Dropped new table OK.
`test9988`.`t` was not altered.
(in cleanup) 2022-12-25T19:02:54 DBD::mysql::db do failed: Lock wait timeout exceeded; try restarting transaction [for Statement "CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END "] at /usr/local/bin/pt-online-schema-change line 11481.
2022-12-25T19:02:54 Dropping triggers...
2022-12-25T19:02:54 Dropped triggers OK.
`test9988`.`t` was not altered.
real 0m10.364s
user 0m0.176s
sys 0m0.019s
2.5.2.检查processlist
10秒后Waiting for table metadata lock消失
mysql> select * from information_schema.processlist where command<>'Sleep' and INFO is not null and user='test'\G
Empty set (0.00 sec)
mysql> select * from information_schema.processlist where command<>'Sleep' and INFO is not null and user='test'\G
*************************** 1. row ***************************
ID: 178
USER: test
HOST: 172.20.23.4:32815
DB: test9988
COMMAND: Query
TIME: 1
STATE: Waiting for table metadata lock
INFO: CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END
1 row in set (0.00 sec)
mysql> select * from information_schema.processlist where command<>'Sleep' and INFO is not null and user='test'\G
*************************** 1. row ***************************
ID: 178
USER: test
HOST: 172.20.23.4:32815
DB: test9988
COMMAND: Query
TIME: 8
STATE: Waiting for table metadata lock
INFO: CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END
1 row in set (0.00 sec)
mysql> select * from information_schema.processlist where command<>'Sleep' and INFO is not null and user='test'\G
*************************** 1. row ***************************
ID: 178
USER: test
HOST: 172.20.23.4:32815
DB: test9988
COMMAND: Query
TIME: 9
STATE: Waiting for table metadata lock
INFO: CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END
1 row in set (0.00 sec)
mysql> select * from information_schema.processlist where command<>'Sleep' and INFO is not null and user='test'\G
Empty set (0.00 sec)
mysql> select * from information_schema.processlist where command<>'Sleep' and INFO is not null and user='test'\G
Empty set (0.00 sec)
2.5.3.检查general log
只尝试1次CREATE TRIGGER后就继续后面的清理操作
2022-12-25T19:02:43.903511+08:00 178 Query USE `test9988`
2022-12-25T19:02:43.903722+08:00 178 Query SHOW CREATE TABLE `test9988`.`t`
2022-12-25T19:02:43.904153+08:00 178 Query /*!40101 SET @@SQL_MODE := @OLD_SQL_MODE, @@SQL_QUOTE_SHOW_CREATE := @OLD_QUOTE */
2022-12-25T19:02:43.904464+08:00 178 Query CREATE TABLE `test9988`.`_t_new` (
`id` int NOT NULL,
`name` varchar(20) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL,
PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_general_ci
2022-12-25T19:02:43.985723+08:00 178 Query ALTER TABLE `test9988`.`_t_new` add index idx_t(name)
2022-12-25T19:02:44.003385+08:00 178 Query /*!40101 SET @OLD_SQL_MODE := @@SQL_MODE, @@SQL_MODE := '', @OLD_QUOTE := @@SQL_QUOTE_SHOW_CREATE, @@SQL_QUOTE_SHOW_CREATE := 1 */
2022-12-25T19:02:44.003699+08:00 178 Query USE `test9988`
2022-12-25T19:02:44.003925+08:00 178 Query SHOW CREATE TABLE `test9988`.`_t_new`
2022-12-25T19:02:44.004319+08:00 178 Query /*!40101 SET @@SQL_MODE := @OLD_SQL_MODE, @@SQL_QUOTE_SHOW_CREATE := @OLD_QUOTE */
2022-12-25T19:02:44.005185+08:00 178 Query SELECT TRIGGER_SCHEMA, TRIGGER_NAME, DEFINER, ACTION_STATEMENT, SQL_MODE, CHARACTER_SET_CLIENT, COLLATION_CONNECTION, EVENT_MANIPULATION, ACTION_TIMING FROM INFORMATION_SCHEMA.TRIGGERS WHERE EVENT_MANIPULATION = 'DELETE' AND ACTION_TIMING = 'AFTER' AND TRIGGER_SCHEMA = 'test9988' AND EVENT_OBJECT_TABLE = 't'
2022-12-25T19:02:44.006205+08:00 178 Query SELECT TRIGGER_SCHEMA, TRIGGER_NAME, DEFINER, ACTION_STATEMENT, SQL_MODE, CHARACTER_SET_CLIENT, COLLATION_CONNECTION, EVENT_MANIPULATION, ACTION_TIMING FROM INFORMATION_SCHEMA.TRIGGERS WHERE EVENT_MANIPULATION = 'UPDATE' AND ACTION_TIMING = 'AFTER' AND TRIGGER_SCHEMA = 'test9988' AND EVENT_OBJECT_TABLE = 't'
2022-12-25T19:02:44.007020+08:00 178 Query SELECT TRIGGER_SCHEMA, TRIGGER_NAME, DEFINER, ACTION_STATEMENT, SQL_MODE, CHARACTER_SET_CLIENT, COLLATION_CONNECTION, EVENT_MANIPULATION, ACTION_TIMING FROM INFORMATION_SCHEMA.TRIGGERS WHERE EVENT_MANIPULATION = 'INSERT' AND ACTION_TIMING = 'AFTER' AND TRIGGER_SCHEMA = 'test9988' AND EVENT_OBJECT_TABLE = 't'
2022-12-25T19:02:44.007872+08:00 178 Query SELECT TRIGGER_SCHEMA, TRIGGER_NAME, DEFINER, ACTION_STATEMENT, SQL_MODE, CHARACTER_SET_CLIENT, COLLATION_CONNECTION, EVENT_MANIPULATION, ACTION_TIMING FROM INFORMATION_SCHEMA.TRIGGERS WHERE EVENT_MANIPULATION = 'DELETE' AND ACTION_TIMING = 'BEFORE' AND TRIGGER_SCHEMA = 'test9988' AND EVENT_OBJECT_TABLE = 't'
2022-12-25T19:02:44.008581+08:00 178 Query SELECT TRIGGER_SCHEMA, TRIGGER_NAME, DEFINER, ACTION_STATEMENT, SQL_MODE, CHARACTER_SET_CLIENT, COLLATION_CONNECTION, EVENT_MANIPULATION, ACTION_TIMING FROM INFORMATION_SCHEMA.TRIGGERS WHERE EVENT_MANIPULATION = 'UPDATE' AND ACTION_TIMING = 'BEFORE' AND TRIGGER_SCHEMA = 'test9988' AND EVENT_OBJECT_TABLE = 't'
2022-12-25T19:02:44.009281+08:00 178 Query SELECT TRIGGER_SCHEMA, TRIGGER_NAME, DEFINER, ACTION_STATEMENT, SQL_MODE, CHARACTER_SET_CLIENT, COLLATION_CONNECTION, EVENT_MANIPULATION, ACTION_TIMING FROM INFORMATION_SCHEMA.TRIGGERS WHERE EVENT_MANIPULATION = 'INSERT' AND ACTION_TIMING = 'BEFORE' AND TRIGGER_SCHEMA = 'test9988' AND EVENT_OBJECT_TABLE = 't'
2022-12-25T19:02:44.010080+08:00 178 Query CREATE TRIGGER `pt_osc_test9988_t_del` AFTER DELETE ON `test9988`.`t` FOR EACH ROW BEGIN DECLARE CONTINUE HANDLER FOR 1146 begin end; DELETE IGNORE FROM `test9988`.`_t_new` WHERE `test9988`.`_t_new`.`id` <=> OLD.`id`; END
2022-12-25T19:02:54.011905+08:00 178 Query SHOW TABLES FROM `test9988` LIKE '\_t\_new'
2022-12-25T19:02:54.014676+08:00 178 Query DROP TABLE IF EXISTS `test9988`.`_t_new`
2022-12-25T19:02:54.026623+08:00 179 Quit
2022-12-25T19:02:54.027843+08:00 178 Query SHOW TABLES FROM `test9988` LIKE '\_t\_ne