后程序 hang 住,不一会返回了2013 错误,即服务器连接异常中断,检查 mysqld error log, 发现在mysqld在将并行复制转化为串行复制的过程中异常 crash,其中错误信息为:

  1. [ERROR] Error creating relay log info: Failed to initialize the worker info structure.

crash 堆栈为:

结合源码仔细分析上面的错误信息不难发现,在启动 SQL 线程初始化 worker 信息的过程中失败,从而引起了空指针异常。

一个简单的 start slave 就能够导致 mysqld crash?应该不会那么简单,编写 testcase,试图在本地重现以上问题,测例如下:

  1. --source include/master-slave.inc
  2. --source include/not_embedded.inc
  3. --source include/not_windows.inc
  4. --connection slave
  5. stop slave;
  6. set global slave_parallel_workers= 1;
  7. start slave;
  8. stop slave;
  9. set global slave_parallel_workers= 0;
  10. start slave;

运行后果然没有能够重现问题,根据研发的同学反映在中断之前有一段时间命令是 hang 住的,于是断定 hang 问题与 crash 应该存在着联系,以上测例并不能将问题重现,于是与求助研发同学进行联调,在 hang 住的时候采集到了以下关键 pt-pmp 信息:

  1. mysql> SELECT r.trx_id waiting_trx_id, r.trx_mysql_thread_id waiting_thread, left(r.trx_query,20) waiting_query, concat(concat(lw.lock_type, ' '), lw.lock_mode) waiting_for_lock, b.trx_id blocking_trx_id, b.trx_mysql_thread_id blocking_thread, left(b.trx_query,20) blocking_query, concat(concat(lb.lock_type, ' '), lb.lock_mode) blocking_lock FROM information_schema.innodb_lock_waits w INNER JOIN information_schema.innodb_trx b ON b.trx_id = w.blocking_trx_id INNER JOIN information_schema.innodb_trx r ON r.trx_id = w.requesting_trx_id INNER JOIN information_schema.innodb_locks lw ON lw.lock_trx_id = r.trx_id INNER JOIN information_schema.innodb_locks lb ON lb.lock_trx_id = b.trx_id\G
  2. *************************** 1. row ***************************
  3. waiting_trx_id: 1313
  4. waiting_thread: 12
  5. waiting_query: NULL
  6. waiting_for_lock: RECORD S
  7. blocking_trx_id: 1312
  8. blocking_thread: 6
  9. blocking_query: start slave
  10. blocking_lock: RECORD X
  11. 1 row in set (0.00 sec)
  12. mysql> show processlist;
  13. | Id | User | Host | db | Command | Time | State | Info |
  14. | 2 | root | localhost:57292 | test | Sleep | 16 | | |
  15. | 3 | root | localhost:57293 | test | Sleep | 16 | | |
  16. | 6 | root | localhost:57299 | test | Query | 15 | Waiting for slave thread to start | start slave |
  17. | 7 | root | localhost:57300 | test | Sleep | 16 | | |
  18. | 11 | system user | | NULL | Connect | 15 | Connecting to master | |
  19. | 12 | system user | | mysql | Connect | 15 | Waiting for the next event in relay log | |
  20. | 13 | root | localhost | test | Query | 0 | init | show processlist |
  21. +----+-------------+-----------------+-------+---------+------+-----------------------------------------+------------------+
  22. 7 rows in set (0.00 sec)

其中 information_schema.innodb_lock_waits,information_schema.innodb_locks,information_schema.innodb_trx 的信息可参考官方文档

从以上信息可以清楚地看到 start slave(blocking_thread: 6)获取了 slave_worker_info 中行记录的X锁,而 sql thread 线程 (waiting_thread: 12) 在获取 S 锁失败引起锁等待,进而获取信息失败返回NULL, 进而造成了空指针引用,mysqld crash,此时 start slave 与 sql thread 的资源竟争如下:

  • start slave thread 获取 slave_work_info 记录的 X 锁,等待 sql thread 已启动的信号量,然后继续运行;
  • sql thread 被启动后,需要根据 slave_worker_info 为进行初始化,因此等待获取相关行的S锁;

因此,start slave thread 与 sql thread 形成了死锁,分析到了现在还有两个疑问没有解释:

  • start slave 为什么会访问 slave_worker_info 且一直持有锁资源?
  • 为什么本地在测试的时候加上 relay_log_info_repository 的设置还是不能重现呢?

继续研究,打开general log 后,发现有许多的 set autocommit=0 的语句,于是感觉可能是 autocommit 的问题,修改后测例如下:

运行后问题终于重现。。。

  • start slave thread 在等待 sql thread 的过程中没有释放其占用的锁资源;
  • sql thread 在初始化 worker 信息时没有处理获取信息失败的情况。

回到上面的问题:

  • start slave 为什么会访问 slave_worker_info 且一直持有锁资源?

    答:start slave 的过程中需要初始化 worker信息,执行 crash recovery 等一系列操作,对于已经执行的不再执行,对于没有执行的继续执行,详情见global_init_infomts_recovery_groups 等函数,在autocommit=0 的情况下,start slave thread 没有commit 或者执行完之前是不会释放锁资源的。

在排查问题的过程中发现 start slave 时会自动提交当前 session 之前已经操作的数据,然后开启一个新的事务,所以在使用 start slave 时要注意这个问题!