暂无图片
暂无图片
暂无图片
暂无图片
暂无图片

xtrabackup备份导致复制中断原因排查

背景

最近有同事发现某个主从复制高可用的业务库的从库晚上的时候总是复制报错,sql thread 自动退出,错误代码是 1317,找我帮忙排查。

排查过程

整个排查过程其实非常简单,只有两的软件要检查。

  • MySQL
  • Xtrabackup

一、检查MySQL

show slave status\G

# 只保留了关键信息
mysql> show slave status\G
*************************** 1. row ***************************
...
Slave_IO_Running: Yes
Slave_SQL_Running: No
...
Last_Errno: 1317
Last_Error: Coordinator stopped because there were error(s) in the worker(s). The most recent failure being: Worker 1 failed executing transaction '6de868b0-e7d3-11ec-b045-000c29375703:41' at master log mysql-bin.000003, end_log_pos 390569732. See error log and/or performance_schema.replication_applier_status_by_worker table for more details about this failure or others, if any.
... 
1 row in set (0.00 sec)

复制

检查从库状态,可以 double comfire 是 sql_thread 挂了,错误代码是 1317,提示可以查询 error log 或者 performance_schema.replication_applier_status_by_worker
表更深入了解情况。

error log

2022-07-05T23:38:52.068794+08:00 3258 [ERROR] Slave SQL for channel '': Worker 1 failed executing transaction '6de868b0-e7d3-11ec-b045-000c29375703:41' at master log mysql-bin.000003, end_log_pos 390569732; Error executing row event: 'Query execution was interrupted', Error_code: 1317
2022-07-05T23:38:52.074955+08:00 3257 [Warning] Slave SQL for channel '': ... The slave coordinator and worker threads are stopped, possibly leaving data in inconsistent state. A restart should restore consistency automatically, although using non-transactional storage for data or info tables or DDL queries could lead to problems. In such cases you have to examine your data (see documentation for details). Error_code: 1756
2022-07-05T23:38:52.080376+08:00 3257 [Note] Slave SQL thread for channel '' exiting, replication stopped in log 'mysql-bin.000003' at position 390569450

复制

performance_schema.replication_applier_status_by_worker 表

*************************** 1. row ***************************
         CHANNEL_NAME: 
            WORKER_ID: 1
            THREAD_ID: NULL
        SERVICE_STATE: OFF
LAST_SEEN_TRANSACTION: 6de868b0-e7d3-11ec-b045-000c29375703:41
    LAST_ERROR_NUMBER: 1317
   LAST_ERROR_MESSAGE: Worker 1 failed executing transaction '6de868b0-e7d3-11ec-b045-000c29375703:41' at master log mysql-bin.000003, end_log_pos 390569732; Error executing row event: 'Query execution was interrupted'
 LAST_ERROR_TIMESTAMP: 2022-07-05 23:38:52
*************************** 2. row ***************************
         CHANNEL_NAME: 
            WORKER_ID: 2
            THREAD_ID: NULL
        SERVICE_STATE: OFF
LAST_SEEN_TRANSACTION: 
    LAST_ERROR_NUMBER: 0
   LAST_ERROR_MESSAGE: 
 LAST_ERROR_TIMESTAMP: 0000-00-00 00:00:00
*************************** 3. row ***************************
         CHANNEL_NAME: 
            WORKER_ID: 3
            THREAD_ID: NULL
        SERVICE_STATE: OFF
LAST_SEEN_TRANSACTION: 
    LAST_ERROR_NUMBER: 0
   LAST_ERROR_MESSAGE: 
 LAST_ERROR_TIMESTAMP: 0000-00-00 00:00:00
*************************** 4. row ***************************
         CHANNEL_NAME: 
            WORKER_ID: 4
            THREAD_ID: NULL
        SERVICE_STATE: OFF
LAST_SEEN_TRANSACTION: 
    LAST_ERROR_NUMBER: 0
   LAST_ERROR_MESSAGE: 
 LAST_ERROR_TIMESTAMP: 0000-00-00 00:00:00
4 rows in set (0.00 sec)

复制

可以看出数据库是使用了 4 个 applier 线程做并行复制。

实际上这三个地方,我获取到的信息是一样的,就是执行 gtid 标号为"6de868b0-e7d3-11ec-b045-000c29375703:41"的 SQL 时,查询 interrupted 了。

根据 gtid 号到 binlog 上查询具体是什么 SQL

根据错误信息,发生问题时是主库的 mysql-bin.000003,gtid 编号"6de868b0-e7d3-11ec-b045-000c29375703:41",很快我查到,是一个很简单的 insert 语句,只插入一行,也不是什么大事务。脱敏后的语句是:

use fander
insert into fander values(1);

复制

读者:  我信你个糟老头子,坏的很

二、检查xtrabackup日志

220705 23:37:50  version_check Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup;mysql_socket=/database/mysql/data/3307/mysqld.sock' as 'admin'  (using password: YES).
220705 23:37:50  version_check Connected to MySQL server
220705 23:37:50  version_check Executing a version check against the server...
220705 23:37:50  version_check Done.
220705 23:37:50 Connecting to MySQL server host: localhost, user: admin, password: set, port: 0, socket: /database/mysql/data/3307/mysqld.sock
Using server version 5.7.38-log
xtrabackup version 2.4.5 based on MySQL server 5.7.13 Linux (x86_64) (revision id: e41c0be)
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /database/mysql/data/3307/
xtrabackup: open files limit requested 0, set to 65536
xtrabackup: using the following InnoDB configuration:
xtrabackup:   innodb_data_home_dir = .
xtrabackup:   innodb_data_file_path = ibdata1:64M:autoextend
xtrabackup:   innodb_log_group_home_dir = /database/mysql/log/redolog/3307
xtrabackup:   innodb_log_files_in_group = 16
xtrabackup:   innodb_log_file_size = 268435456
InnoDB: Number of pools: 1
220705 23:37:50 >> log scanned up to (2778356)
InnoDB: Opened 2 undo tablespaces
InnoDB: 0 undo tablespaces made active
xtrabackup: Generating a list of tablespaces
InnoDB: Allocated tablespace ID 4 for mysql/plugin, old maximum was 2
xtrabackup: Starting 4 threads for parallel data files transfer
220705 23:37:51 [01] Compressing ./ibdata1 to /backup/ibdata1.qp
220705 23:37:51 [04] Compressing ./mysql/plugin.ibd to /backup/mysql/plugin.ibd.qp
220705 23:37:51 [03] Compressing .//undo002 to /backup/undo002.qp
220705 23:37:51 [02] Compressing .//undo001 to /backup/undo001.qp
220705 23:37:51 [04]        ...done
220705 23:37:51 [04] Compressing ./mysql/servers.ibd to /backup/mysql/servers.ibd.qp
220705 23:37:51 [04]        ...done
220705 23:37:51 [04] Compressing ./mysql/help_topic.ibd to /backup/mysql/help_topic.ibd.qp
220705 23:37:51 [03]        ...done
220705 23:37:51 [03] Compressing ./mysql/help_category.ibd to /backup/mysql/help_category.ibd.qp
220705 23:37:51 [03]        ...done
220705 23:37:51 [03] Compressing ./mysql/help_relation.ibd to /backup/mysql/help_relation.ibd.qp
220705 23:37:51 [02]        ...done
220705 23:37:51 [02] Compressing ./mysql/help_keyword.ibd to /backup/mysql/help_keyword.ibd.qp
220705 23:37:51 [03]        ...done
220705 23:37:51 [03] Compressing ./mysql/time_zone_name.ibd to /backup/mysql/time_zone_name.ibd.qp
...
220705 23:37:51 >> log scanned up to (2778356)
220705 23:37:52 [01]        ...done
220705 23:37:52 Executing FLUSH TABLES WITH READ LOCK...
220705 23:37:52 Kill query timeout 60 seconds.
220705 23:37:52 >> log scanned up to (2778356)
220705 23:37:53 >> log scanned up to (2778356)
220705 23:37:54 >> log scanned up to (2778356)
220705 23:37:55 >> log scanned up to (2778356)
220705 23:37:56 >> log scanned up to (2778356)
220705 23:37:57 >> log scanned up to (2778356)
220705 23:37:58 >> log scanned up to (2778356)
220705 23:37:59 >> log scanned up to (2778356)
...
220705 23:38:52 Connecting to MySQL server host: localhost, user: admin, password: set, port: 0, socket: /database/mysql/data/3307/mysqld.sock
220705 23:38:52 Killing query 3258 (duration 61 sec): insert into fander values(1)
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 >> log scanned up to (2778473)
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Killing query 4660 (duration 72 sec): select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
220705 23:38:52 Kill query thread stopped
220705 23:38:52 Starting to backup non-InnoDB tables and files
220705 23:38:52 [01] Compressing ./mysql/db.opt to /backup/mysql/db.opt.qp
220705 23:38:52 [01]        ...done
220705 23:38:52 [01] Compressing ./mysql/db.frm to /backup/mysql/db.frm.qp
220705 23:38:52 [01]        ...done
220705 23:38:52 [01] Compressing ./mysql/db.MYI to /backup/mysql/db.MYI.qp
220705 23:38:52 [01]        ...done
220705 23:38:52 [01] Compressing ./mysql/db.MYD to /backup/mysql/db.MYD.qp
220705 23:38:52 [01]        ...done
220705 23:38:52 [01] Compressing ./mysql/user.frm to /backup/mysql/user.frm.qp
220705 23:38:52 [01]        ...done
...
220705 23:38:53 [01] Compressing ./fander/test_myisam.MYD to /backup/fander/test_myisam.MYD.qp
220705 23:38:53 >> log scanned up to (2778473)
220705 23:38:54 [01]        ...done
220705 23:38:54 Finished backing up non-InnoDB tables and files
220705 23:38:54 [00] Compressing xtrabackup_binlog_info
220705 23:38:54 [00]        ...done
220705 23:38:54 Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS...
xtrabackup: The latest check point (for incremental): '2778464'
xtrabackup: Stopping log copying thread.
220705 23:38:54 >> log scanned up to (2778473)
...
220705 23:38:54 Executing UNLOCK TABLES
220705 23:38:54 All tables unlocked
220705 23:38:54 [00] Compressing ib_buffer_pool to /backup/ib_buffer_pool.qp
220705 23:38:54 [00]        ...done
220705 23:38:54 Backup created in directory '/backup/'
MySQL binlog position: filename 'mysql-bin.000002', position '390570205', GTID of the last change '6de868b0-e7d3-11ec-b045-000c29375703:1-40'
220705 23:38:54 [00] Compressing backup-my.cnf
220705 23:38:54 [00]        ...done
220705 23:38:54 [00] Compressing xtrabackup_info
220705 23:38:54 [00]        ...done
xtrabackup: Transaction log of lsn (2774121) to (2778473) was copied.
220705 23:38:54 completed OK!

复制

注意看标黄的部分,xtrabackup 除了 kill 了一个大查询外,还把我的 insert kill 掉了,而这个 SQL 是从库的 WORKER_ID=1 的 applier 线程执行的,是并行复制的工作线程,归属于 sql thread 线程,所以 sql thread 线程就挂了。

xtrabackup备份导致复制中断。

为什么xtrabackup会kill SQL

检查备份脚本发现,命令如下:

xtrabackup --datadir=/database/mysql/data/3307/ \
  --user=admin --password=fanderpasswd --socket=/database/mysql/data/3307/mysqld.sock \
  --backup --target-dir=/backup/  --compress --parallel=4 --compress-threads=2 \
  --lock-wait-timeout=120 --lock-wait-threshold=120 --lock-wait-query-type=all \
  --kill-long-queries-timeout=60 --kill-long-query-type=all  2> backup.log

复制

关键参数:

  • --kill-long-queries-timeout=60

此参数表示杀死查询前等待长查询多少秒,我的脚本设置了 60 秒

  • --kill-long-query-type=all

此参数表示杀死的查询的类型,all 表示所有类型,另外可以可以设置 select,只杀 select

现在,我们回过头来看看"xtrabackup日志"里的过程,在 xtrabackup 备份完 innodb 表后,他需要 flush table with read lock (以下简称为 FTWRL ),对整库上只读锁,再备份非 innodb 表来获得全局一致性。但执行这个 FTWRL 代价是比较大的,他需要获取一些 MDL 锁,而其他事务可能持有了这些锁,所以同事的备份脚本为了备份成功必须保证能获取到这些锁,所以配置了 kill SQL 参数,从而导致了 insert 的那个 SQL 被 kill,导致了 sql thread 崩溃。

明显同事的玩法和我的不一样,平时我会选择另外一个做法,使用  --ftwrl-wait-timeout=30(单位秒),来表示获取不到 FTWRL 就放弃备份。也就是在杀 SQL 和放弃备份之间,我平时是选择后者。

现在一些新手读者们有一些疑问了:

  1. FTWRL 是什么,到底要获取什么锁,要这么大动干戈把别的 SQL 干掉。
  2. 为什么我的 insert 语句 SQL 那么简单,"xtrabackup日志" 里显示慢到要执行 61 秒?

FTWRL 是什么?

FLUSH TABLES WITH READ LOCK(FTWRL),最常用于备份工具获取一致性备份(数据与binlog位点匹配)。

有些同学可能以为,他的作用就只是给整个数据库加一个全局读锁,只做这一件事。

而有些同学听名字,其实能猜到他要干两件事,第一件事是 FLUSH TABLES,让表缓存刷到磁盘,第二件事是同时要加个全局读锁,不允许有数据写入表了。

而实际上他干了三件事,有先后顺序,可以称为三个阶段:

  1. 上全局读锁,防止新的写入 (lock_global_read_lock)
  2. 清理表缓存,让表缓存数据刷盘 (close_cached_tables)
  3. 上全局 COMMIT 锁,防止已经执行完的写入型事务提交 (make_global_read_lock_block_commit)

这样的数据,才能保证不会变化,我们才用备份工具物理拷贝走,或者做一个系统级快照来备份。

我们可以做实验,证明这三个状态的存在。

1. 观察上全局读锁阶段

session 1:
mysql> flush table with read lock;
Query OK, 0 rows affected (0.01 sec)

session 2:
mysql> insert into fander.fander values(1);
# 新写入被 FTWRL 阻塞

session 3:
mysql> show processlist;
+------+-------+-----------------------+--------+------------------+-------+---------------------------------------------------------------+-------------------------------------+
| Id   | User  | Host                  | db     | Command          | Time  | State                                                         | Info                                |
+------+-------+-----------------------+--------+------------------+-------+---------------------------------------------------------------+-------------------------------------+
| 4415 | admin | 127.0.0.1:64670       | NULL   | Sleep            |   116 |                                                               | NULL                                |
| 4416 | admin | 127.0.0.1:64672       | fander | Query            |    99 | Waiting for global read lock                                  | insert into fander.fander values(1) |
4417 | admin | 127.0.0.1:64674       | NULL   | Query            |     0 | starting                                                      | show processlist                    |
+------+-------+-----------------------+--------+------------------+-------+---------------------------------------------------------------+-------------------------------------+
3 rows in set (0.00 sec)

复制

FTWRL 执行成功,持有了全局读锁,新来的插入被阻塞,卡在 "Waiting for global read lock" ,说明了 FTWRL 会去获取和持有 global read lock。

2. 观察清理表缓存阶段

session 1:
#我造了一个长查询,笛卡尔积
select * from test_myisam a join test_myisam b order by a.a limit 10\G

session 2:
mysql> flush tables with read lock;
# FTWRL 被长查询阻塞

session 3:
mysql> show processlist;
+------+-------+-----------------------+--------+------------------+------+---------------------------------------------------------------+----------------------------------------------------------------------+
| Id   | User  | Host                  | db     | Command          | Time | State                                                         | Info                                                                 |
+------+-------+-----------------------+--------+------------------+------+---------------------------------------------------------------+----------------------------------------------------------------------+
| 4415 | admin | 127.0.0.1:64670       | fander | Query            |  453 | Sending data                                                  | select * from test_myisam a join test_myisam b order by a.a limit 10 |
4416 | admin | 127.0.0.1:64672       | fander | Query            |  407 | Waiting for table flush                                       | flush tables with read lock                                          |
4451 | admin | 127.0.0.1:64876       | NULL   | Query            |    0 | starting                                                      | show processlist                                                     |
+------+-------+-----------------------+--------+------------------+------+---------------------------------------------------------------+----------------------------------------------------------------------+
3 rows in set (0.00 sec)

复制

FLUSH TABLES 清理表缓存阶段,需要关闭所有表,把表缓存刷到磁盘,案例里有个长查询一直没有结束,导致 FTWRL 被阻塞,卡在"Waiting for table flush",说明 FTWRL 需要等待 table flush。

3. 观察上全局 COMMIT 锁阶段

session 1:
mysql> begin;insert into fander values(1);
Query OK, 0 rows affected (0.00 sec)

Query OK, 1 row affected (0.00 sec)

session 2:
mysql> flush table with read lock;
Query OK, 0 rows affected (0.00 sec)

session 1:
mysql> commit;
# commit 被 FTWRL 阻塞

session 3:
mysql> show processlist;
+----+-------+-----------------------+--------+------------------+------+---------------------------------------------------------------+------------------+
| Id | User  | Host                  | db     | Command          | Time | State                                                         | Info             |
+----+-------+-----------------------+--------+------------------+------+---------------------------------------------------------------+------------------+
|  6 | admin | 127.0.0.1:1029        | NULL   | Query            |    0 | starting                                                      | show processlist |
|  7 | admin | 127.0.0.1:1031        | fander | Query            |    5 | Waiting for commit lock                                       | commit           |
|  8 | admin | 127.0.0.1:1035        | NULL   | Sleep            |    9 |                                                               | NULL             |
+----+-------+-----------------------+--------+------------------+------+---------------------------------------------------------------+------------------+
3 rows in set (0.00 sec)

复制

案例中,执行 insert 事务不提交,然后 FTWRL 可以成功,但 insert 事务提交会卡在"Waiting for commit lock",说明了 FTWRL 获取和持有了 commit lock。

我解释了 FTWRL 是什么,获取了什么锁,至于为什么要大动干戈把别的 SQL 干掉,原因就是 FTWRL 会争抢锁,如果长时间获取不了需要的锁,会造成 SQL 堵塞,最终就得抉择要么 kill FTWRL(放弃备份),要么 kill SQL。

我这里只是给出简单原理和观察方法,详细的原理请查看官方文档。

推断当时可能的场景

为什么我的 insert 语句 SQL 那么简单,"xtrabackup日志" 里显示慢到要执行 61 秒? 我尝试一下完全模拟当时的场景,我会列举几种可能场景,由于 FTWRL 等待了 60秒,而日志显示那个长查询执行了 72 秒,insert 这个SQL 执行了 61 秒,所以理论上这两个 SQL 都开始于 FTWRL 之前。

第一种可能,insert 开始于 FTWRL 之前,模拟1 之 insert 晚提交

  1. 在从库上执行一个长查询
  2. 从库跑完了一个 insert,在 Sleep 状态尚未 commit
  3. xtrabackup 走到 FTWRL 流程
  4. 这个 insert commit。(2、4之间很短暂,之间穿插了 3 的 FTWRL)

这个流程不一定要在从库上模拟,在单机上模拟就可以了,以下是步骤:

session 1:
#我造了一个长查询,笛卡尔积
select * from test_myisam a join test_myisam b order by a.a limit 10\G

session 2:
mysql> begin;insert into fander values(1);
Query OK, 0 rows affected (0.00 sec)

Query OK, 1 row affected (0.00 sec)

session 3:
mysql> flush table with read lock;
Query OK, 0 rows affected (0.00 sec)

session 4:
+----+-------+-----------------------+--------+------------------+------+---------------------------------------------------------------+----------------------------------------------------------------------+
| Id | User  | Host                  | db     | Command          | Time | State                                                         | Info                                                                 |
+----+-------+-----------------------+--------+------------------+------+---------------------------------------------------------------+----------------------------------------------------------------------+
|  6 | admin | 127.0.0.1:2207        | fander | Query            |   26 | Sending data                                                  | select * from test_myisam a join test_myisam b order by a.a limit 10 |
| 11 | admin | 127.0.0.1:2285        | fander | Sleep            |   13 |                                                               | NULL                                                                 |
| 12 | admin | 127.0.0.1:2305        | NULL   | Query            |    4 | Waiting for table flush                                       | flush table with read lock                                           |
| 13 | admin | 127.0.0.1:2317        | NULL   | Query            |    0 | starting                                                      | show processlist                                                     |
+----+-------+-----------------------+--------+------------------+------+---------------------------------------------------------------+----------------------------------------------------------------------+
4 rows in set (0.00 sec)

session 2:
mysql> commit;
Query OK, 0 rows affected (0.04 sec)


session 4:
# show processlist 没变化
mysql> show processlist;
+----+-------+-----------------------+--------+------------------+------+---------------------------------------------------------------+----------------------------------------------------------------------+
| Id | User  | Host                  | db     | Command          | Time | State                                                         | Info                                                                 |
+----+-------+-----------------------+--------+------------------+------+---------------------------------------------------------------+----------------------------------------------------------------------+
|  6 | admin | 127.0.0.1:2207        | fander | Query            |   98 | Sending data                                                  | select * from test_myisam a join test_myisam b order by a.a limit 10 |
| 11 | admin | 127.0.0.1:2285        | fander | Sleep            |    6 |                                                               | NULL                                                                 |
| 12 | admin | 127.0.0.1:2305        | NULL   | Query            |   76 | Waiting for table flush                                       | flush table with read lock                                           |
| 13 | admin | 127.0.0.1:2317        | NULL   | Query            |    0 | starting                                                      | show processlist                                                     |
+----+-------+-----------------------+--------+------------------+------+---------------------------------------------------------------+----------------------------------------------------------------------+
4 rows in set (0.00 sec)

复制

session 1 长查询在跑,session 3 的 FTWRL 被 1 阻塞,卡在了三阶段(上全局读锁、清理表缓存、上全局 COMMIT 锁)中的第二阶段"清理表缓存"阶段,没进入第三阶段"上全局 COMMIT 锁"阶段,所以 FTWRL 没有去争抢 COMMIT LOCK,所以 session 2 可以获取 COMMIT LOCK 从而 commit OK。既然 insert 这个 SQL commit OK了,那就和我们观察到的 insert SQL 执行很长时间并且被 kill 的现象不吻合。

第一种可能猜测失败。

第二种可能 insert 开始于 FTWRL 之前,模拟2 之 insert 跑得慢

  1. 在从库上执行一个长查询
  2. 从库在执行一个 insert,不知道为什么跑很慢,在 Query 状态
  3. xtrabackup 走到 FTWRL 流程

为了模拟 2 中的慢,我改为使用一个无主键的表做 delete 操作(和 insert 一样是 DML 操作),造成从库回放慢。

然后我们 show processlist 看看。(留意标黄部分)

mysql> show processlist;
+----+-------------+-----------------+--------+---------+------+--------------------------------------------------------+----------------------------------------------------------------------+
| Id | User        | Host            | db     | Command | Time | State                                                  | Info                                                                 |
+----+-------------+-----------------+--------+---------+------+--------------------------------------------------------+----------------------------------------------------------------------+
|  8 | admin       | 127.0.0.1:62275 | NULL   | Query   |    0 | starting                                               | show processlist                                                     |
|  9 | system user |                 | NULL   | Connect |  157 | Waiting for master to send event                       | NULL                                                                 |
| 10 | system user |                 | NULL   | Connect |   10 | Slave has read all relay log; waiting for more updates | NULL                                                                 |
| 11 | system user |                 | NULL   | Connect |   18 | Executing event                                        | delete  from test_innodb where id <50000 limit 40000                 |
| 12 | system user |                 | NULL   | Connect |  157 | Waiting for an event from Coordinator                  | NULL                                                                 |
| 13 | system user |                 | NULL   | Connect |  157 | Waiting for an event from Coordinator                  | NULL                                                                 |
| 14 | system user |                 | NULL   | Connect |  157 | Waiting for an event from Coordinator                  | NULL                                                                 |
| 21 | admin       | 127.0.0.1:62315 | fander | Query   |   29 | Sending data                                           | select * from test_myisam a join test_myisam b order by a.a limit 10 |
| 23 | admin       | localhost       | NULL   | Query   |    8 | Waiting for global read lock                           | FLUSH TABLES WITH READ LOCK                                          |
+----+-------------+-----------------+--------+---------+------+--------------------------------------------------------+----------------------------------------------------------------------+
9 rows in set (0.00 sec)

mysql> show processlist;
+----+-------------+-----------------+--------+---------+------+--------------------------------------------------------+----------------------------------------------------------------------+
| Id | User        | Host            | db     | Command | Time | State                                                  | Info                                                                 |
+----+-------------+-----------------+--------+---------+------+--------------------------------------------------------+----------------------------------------------------------------------+
|  8 | admin       | 127.0.0.1:62275 | NULL   | Query   |    0 | starting                                               | show processlist                                                     |
|  9 | system user |                 | NULL   | Connect |  178 | Waiting for master to send event                       | NULL                                                                 |
| 10 | system user |                 | NULL   | Connect |   31 | Slave has read all relay log; waiting for more updates | NULL                                                                 |
| 11 | system user |                 | NULL   | Connect |   39 | Waiting for an event from Coordinator                  | NULL                                                                 |
| 12 | system user |                 | NULL   | Connect |  178 | Waiting for an event from Coordinator                  | NULL                                                                 |
| 13 | system user |                 | NULL   | Connect |  178 | Waiting for an event from Coordinator                  | NULL                                                                 |
| 14 | system user |                 | NULL   | Connect |  178 | Waiting for an event from Coordinator                  | NULL                                                                 |
| 21 | admin       | 127.0.0.1:62315 | fander | Query   |   50 | Sending data                                           | select * from test_myisam a join test_myisam b order by a.a limit 10 |
| 23 | admin       | localhost       | NULL   | Query   |   29 | Waiting for table flush                                | FLUSH TABLES WITH READ LOCK                                          |
+----+-------------+-----------------+--------+---------+------+--------------------------------------------------------+----------------------------------------------------------------------+
9 rows in set (0.00 sec)

mysql> show processlist;
+----+-------------+-----------------+------+---------+------+--------------------------------------------------------+------------------+
| Id | User        | Host            | db   | Command | Time | State                                                  | Info             |
+----+-------------+-----------------+------+---------+------+--------------------------------------------------------+------------------+
|  8 | admin       | 127.0.0.1:62275 | NULL | Query   |    0 | starting                                               | show processlist |
|  9 | system user |                 | NULL | Connect |  224 | Waiting for master to send event                       | NULL             |
| 10 | system user |                 | NULL | Connect |   77 | Slave has read all relay log; waiting for more updates | NULL             |
| 11 | system user |                 | NULL | Connect |   85 | Waiting for an event from Coordinator                  | NULL             |
| 12 | system user |                 | NULL | Connect |  224 | Waiting for an event from Coordinator                  | NULL             |
| 13 | system user |                 | NULL | Connect |  224 | Waiting for an event from Coordinator                  | NULL             |
| 14 | system user |                 | NULL | Connect |  224 | Waiting for an event from Coordinator                  | NULL             |
+----+-------------+-----------------+------+---------+------+--------------------------------------------------------+------------------+
7 rows in set (0.00 sec)

复制

在 FTWRL 跑到 29 秒时,这个 delete 执行完后就 commit 成功了,那就和我们观察到的 insert SQL 执行很长时间并且被 kill 的现象不吻合。

第二种可能猜测失败。

前面提到了,select 大查询 和 insert 分别是执行了 72 秒和 61 秒被 kill 的,而 FTWRL 是等待 60 秒开始 kill SQL 的,也就是触发 kill 操作时,FTWRL 应该运行时间正好是 60 秒。所以他们有严格的执行的先后顺序

1.select 大查询
2.insert
3.FTWRL

所以只有上面两种可能,但测试发现都不是,于是我只好测试下面这种可能了

第三种可能,insert 开始于 FTWRL 之前,模拟 3 之不停 insert

  1. 在从库上执行一个长查询
  2. 不停地在主库发起 insert 查询,利用主从复制使从库执行了 insert 语句
  3. 跑备份任务,观察 FTWRL 步骤
console 1: 从库
#我造了一个长查询,笛卡尔积
mysql> select * from test_myisam a join test_myisam b order by a.a limit 10\G

console 2: 主库上
# 不停地 insert
mysql> insert into fander values(1); #手动重复执行 * N 次

console 3: 从库主机上
[root@192-168-199-132 ~]# xtrabackup --datadir=/database/mysql/data/3307/ --user=admin --password=fanderpasswd --socket=/database/mysql/data/3307/mysqld.sock --backup --target-dir=/backup/  --compress --parallel=4 --compress-threads=2 --lock-wait-timeout=120 --lock-wait-threshold=120 --kill-long-queries-timeout=60 --kill-long-query-type=all --lock-wait-query-type=all 

console 4: 从库上
mysql> show processlist;
+------+-------------+-----------------+--------+---------+---------+---------------------------------------------+----------------------------------------------------------------------+
| Id   | User        | Host            | db     | Command | Time    | State                                       | Info                                                                 |
+------+-------------+-----------------+--------+---------+---------+---------------------------------------------+----------------------------------------------------------------------+
|    5 | system user |                 | NULL   | Connect | 2282498 | Waiting for master to send event            | NULL                                                                 |
| 4999 | system user |                 | NULL   | Connect |      13 | Waiting for dependent transaction to commit | NULL                                                                 |
| 5000 | system user |                 | NULL   | Connect |      16 | Waiting for global read lock                | insert into fander values(1)                                         |
| 5001 | system user |                 | NULL   | Connect |    6646 | Waiting for an event from Coordinator       | NULL                                                                 |
| 5002 | system user |                 | NULL   | Connect |    6646 | Waiting for an event from Coordinator       | NULL                                                                 |
| 5003 | system user |                 | NULL   | Connect |    6646 | Waiting for an event from Coordinator       | NULL                                                                 |
| 5295 | admin       | 127.0.0.1:47717 | fander | Sleep   |    1062 |                                             | NULL                                                                 |
| 5296 | admin       | 127.0.0.1:47721 | NULL   | Query   |       0 | starting                                    | show processlist                                                     |
| 5352 | admin       | 127.0.0.1:47987 | fander | Query   |      42 | Sending data                                | select * from test_myisam a join test_myisam b order by a.a limit 10 |
| 5356 | admin       | localhost       | NULL   | Query   |      13 | Waiting for table flush                     | FLUSH TABLES WITH READ LOCK                                          |
+------+-------------+-----------------+--------+---------+---------+---------------------------------------------+----------------------------------------------------------------------+
13 rows in set (0.00 sec)

mysql> show processlist;
+------+-------------+-----------------+--------+---------+---------+----------------------------------+------------------+
| Id   | User        | Host            | db     | Command | Time    | State                            | Info             |
+------+-------------+-----------------+--------+---------+---------+----------------------------------+------------------+
|    5 | system user |                 | NULL   | Connect | 2282603 | Waiting for master to send event | NULL             |
| 5295 | admin       | 127.0.0.1:47717 | fander | Sleep   |    1167 |                                  | NULL             |
| 5296 | admin       | 127.0.0.1:47721 | NULL   | Query   |       0 | starting                         | show processlist |
+------+-------------+-----------------+--------+---------+---------+----------------------------------+------------------+
7 rows in set (0.01 sec)



# xtrabackup 日志
220706 03:09:09 Killing query 5000 (duration 63 sec): insert into fander values(1)
220706 03:09:09 Killing query 5352 (duration 89 sec): select * from test_myisam a join test_myisam b order by a.a limit 10



复制

模拟出来了,惊奇地发现,明明 show processlist 显示,FTWRL 运行了 13秒 的时候,insert 运行了 16秒,也就是先运行了 insert 过 3 秒后,才运行了 FTWRL,但为什么 insert 会被后运行的 FTWRL 堵住呢?不合理啊。

原理上,先 FTWRL,FTWRL 抢夺成功"global read lock"锁,insert 作为后来者才会被堵住。 

从测试结果,我只能这么解释了,先执行的 insert,不知道为什么没有获取到"global read lock"锁,而后来者 FTWRL 一来就获取到"global read lock"锁了,这时 insert 才开始获取"global read lock"锁,就发生了"Waiting for global read lock",被阻塞了。

我只能自圆其说了,因为更神奇的是,后续我无论如何手工模拟都模拟不出来这个 "第三种情况" 场景了

无论如何,我模拟出了符合生产发生的案例 —— 61 秒被 kill,我模拟的案例甚至是 63 秒被 kill 呢,总之是比 60 秒要大。我当时没有开 general.log,我没法进一步分析了。


然后我测了第四种场景。

第四种可能,模拟 insert 发生在 FTWRL 之后

我写了一个脚本,如下:

[root@192-168-199-131 ~]# cat test.sh 
while true
do
  mysql -uadmin -pfanderpasswd -h192.168.199.132 -P3307 -NBe "show processlist" |grep "FLUSH TABLES WITH READ LOCK" \
  && mysql -uadmin -pfanderpasswd -h127.0.0.1 -P3307 -e "insert into fander.fander values (1)" && exit
done

复制

脚本内容是,如果在从库上探测到 FTWRL ,就会主库执行插入一条 insert 然后退出脚本,探测不到则什么都不干继续循环探测。这样我能保证这个 insert 在主库插入(之后复制到从库)的行为,肯定在 FTWRL 之后执行。

这个模拟可以认为他两发生的先后顺序是:

  1. FTWRL     2. insert

并且发生的时间非常相近,应该相差在几十毫秒内。

我们现在再看看 show processlist 里的秒数(标黄)

console 1: 从库
#我造了一个长查询,笛卡尔积
mysql> select * from test_myisam a join test_myisam b order by a.a limit 10\G

console 2: 主库上
# 执行脚本
[root@192-168-199-131 ~]# sh -x test.sh 

console 3: 从库主机上
[root@192-168-199-132 ~]# xtrabackup --datadir=/database/mysql/data/3307/ --user=admin --password=fanderpasswd --socket=/database/mysql/data/3307/mysqld.sock --backup --target-dir=/backup/  --compress --parallel=4 --compress-threads=2 --lock-wait-timeout=120 --lock-wait-threshold=120 --kill-long-queries-timeout=60 --kill-long-query-type=all --lock-wait-query-type=all 


console 4: 从库上
mysql> show processlist;
+-------+-------------+-----------------+--------+---------+---------+--------------------------------------------------------+----------------------------------------------------------------------+
| Id    | User        | Host            | db     | Command | Time    | State                                                  | Info                                                                 |
+-------+-------------+-----------------+--------+---------+---------+--------------------------------------------------------+----------------------------------------------------------------------+
|     5 | system user |                 | NULL   | Connect | 2438845 | Waiting for master to send event                       | NULL                                                                 |
|  5375 | system user |                 | NULL   | Connect |      54 | Slave has read all relay log; waiting for more updates | NULL                                                                 |
|  5376 | system user |                 | NULL   | Connect |      54 | Waiting for global read lock                           | insert into fander.fander values (1)                                 |
|  5377 | system user |                 | NULL   | Connect |  156049 | Waiting for an event from Coordinator                  | NULL                                                                 |
|  5378 | system user |                 | NULL   | Connect |  156049 | Waiting for an event from Coordinator                  | NULL                                                                 |
|  5379 | system user |                 | NULL   | Connect |  156049 | Waiting for an event from Coordinator                  | NULL                                                                 |
| 15665 | admin       | 127.0.0.1:60619 | fander | Query   |      74 | Sending data                                           | select * from test_myisam a join test_myisam b order by a.a limit 10 |
| 15666 | admin       | 127.0.0.1:60623 | NULL   | Query   |       0 | starting                                               | show processlist                                                     |
| 15667 | admin       | 127.0.0.1:60627 | NULL   | Sleep   |     113 |                                                        | NULL                                                                 |
| 15979 | admin       | localhost       | NULL   | Query   |      54 | Waiting for table flush                                | FLUSH TABLES WITH READ LOCK                                          |
+-------+-------------+-----------------+--------+---------+---------+--------------------------------------------------------+----------------------------------------------------------------------+
10 rows in set (0.00 sec)

mysql> show processlist;
+-------+-------------+-----------------+------+---------+---------+----------------------------------+------------------+
| Id    | User        | Host            | db   | Command | Time    | State                            | Info             |
+-------+-------------+-----------------+------+---------+---------+----------------------------------+------------------+
|     5 | system user |                 | NULL | Connect | 2438863 | Waiting for master to send event | NULL             |
| 15666 | admin       | 127.0.0.1:60623 | NULL | Query   |       0 | starting                         | show processlist |
| 15667 | admin       | 127.0.0.1:60627 | NULL | Sleep   |     131 |                                  | NULL             |
+-------+-------------+-----------------+------+---------+---------+----------------------------------+------------------+
3 rows in set (0.01 sec)


复制

我们可以看到 FTWRL 和 insert 在 Time 列上秒数是相等的。所以在 FTWRL 执行到 60秒时,insert 也是执行到 60秒,会被 kill。

从现象上看是合理的,但从精度来说,insert 是发生在 FTWRL 之后的,如果 FTWRL 执行了 60 秒,而 insert 肯定执行没有 60 秒,可能是 59.999 秒,所以他不应该被 kill。

我把脚本调整,让其发现从库 FTWRL 之后等待 0.2 秒后再执行 insert,测试好几次,也有偶尔会发生 insert 被 kill 事件。

[root@192-168-199-131 ~]# cat test.sh 
while true
do
  mysql -uadmin -pfanderpasswd -h192.168.199.132 -P3307 -NBe "show processlist" |grep "FLUSH TABLES WITH READ LOCK" \
  && sleep 0.2 \
  && mysql -uadmin -pfanderpasswd -h127.0.0.1 -P3307 -e "insert into fander.fander values (1)" && exit
done

复制

所以,这个精度不高的问题,比我想象中还严重,我觉得 percona 应该做优化,这个场景明显不需要 kill insert,因为 kill select 就能解决阻塞。

我把脚本再调整,让其发现从库 FTWRL 之后等待 1 秒后再执行 insert,测试好多次不会误 kill 这个 insert 了。

我的结论是: 

对于 xtrabackup 的 --kill-long-queries-timeout=60
这个功能,他如果触发了 kill 操作,在 kill 的时候可能会把 FTWRL 后面几百毫秒内执行的 SQL 也误 kill 了,这个误伤概率还挺大,如果是从库,这个时候复制的 sql_thread 线程就被 kill 挂了。

所以我们根本解决办法就是避免他触发 kill 操作,那就是不要有刚才那个 72 秒的,大于 --kill-long-queries-timeout=60
定义的大查询。

问题根本原因找到了

当时我们这套主从前面是有做读写分离的,所以从库是会有查询的,但想了一下,半夜谁每天都上来搞个大查询啊?这不对。

select * from test_myisam a join test_myisam b order by a.a limit 10\G
是我做实验伪造的。

而检查 xtrabackup 日志可以发现 线上当时真实的 SQL 是select xxx from mysql.slow_log where start_time >(CURRENT_TIMESTAMP(6) - interval 2 hour) group by sql_text,user_host,db order by avg(query_time) desc limit 10
,这条 SQL 是监控平台去获取慢查询日志做慢查询分析的自动化执行的 SQL。

检查发现监控平台做自动收集慢查询分析的逻辑是: 优先拉取 mysql.slow_log 表,没有数据则视乎有没有足够的操作系统权限,去拉取 slow.log 这个 file。

当时这个 mysql.slow.log 已经积累到 22GB 了,并且由于这个表不是 innodb 引擎,是 CSV 引擎,无法加索引,刚才那个 72 秒的大查询实际上是一个全表扫描。也很好解释,以前没有经常复制中断是因为这个查询并不会慢于 60 秒,随着表越来越大,这个查询最终查询时间超过 60 秒了。

整改

问题原因找到了,整改那就很简单了。

修改参数:

set global log_output = FILE,TABLE
改为
set global log_output = FILE

复制

清空 slow.log 表

mysql> truncate table mysql.slow_log;

复制

总结

我发现 percona xtrabackup 的一个不足。另外我还发现了一个解释不了的现象,我自圆其说了,但也请小伙伴们帮我解释。


最后修改时间:2023-05-26 16:28:07
文章转载自芬达的数据库学习笔记,如果涉嫌侵权,请发送邮件至:contact@modb.pro进行举报,并提供相关证据,一经查实,墨天轮将立刻删除相关内容。

评论