故障分析 | 为什么你的 show slave status 会卡住？

爱可生开源社区

发布于 2024-09-14 18:50:58

600

发布于 2024-09-14 18:50:58

文章被收录于专栏：爱可生开源社区

作者：徐文梁，爱可生 DBA 成员，公众号[DBA修行之路]主理人。一个执着于技术的数据库工程师，主要负责数据库日常运维工作。擅长 MySQL，Redis 等数据库。喜欢垂钓，看风景，结交新朋友，看书，技术总结。

爱可生开源社区出品，原创内容未经授权不得随意使用，转载请联系小编并注明来源。

本文约 3000 字，预计阅读需要 8 分钟。

1问题背景

在数据库 MySQL 的日常运维中，生产环境一般都是 1 主 N 从的高可用架构。涉及主从同步的问题，通常执行 show slave status 命令就可以了解主从实例之间的同步状态，但是凡事总会有意外。

最近在生产环境中遇到 show slave status 命令执行卡住了的情况。以前在测试环境也遇到过，但是并没有深究，但这次是被客户问到了，发现自己说不清楚。如果此时此刻正在阅读本文的读者朋友您也不说清楚，那请随我去源码中一探究竟吧！

2问题分析

执行 show slave status 卡住，为了更全面地了解 MySQL 的状态，通过 pstack 拿到了相应的线程信息。这里保留关键信息，如下：

Thread 6 (Thread 0xxxx (LWP xxx)):
#0  0x..... in __lll_lock_wait () from /lib64/libpthread.so.0
#1  0x..... in _L_lock_975 () from /lib64/libpthread.so.0
#2  0x..... in pthread_mutex_lock () from /lib64/libpthread.so.0
#3  0x..... in inline_mysql_mutex_lock (that=0x1358520 <LOCK_active_mi>, src_file=<optimized out>, src_line=<optimized out>) at .../mysql-5.6.40/include/mysql/psi/mysql_thread.h:688
#4  0x..... in mysql_execute_command (thd=thd@entry=0x5d0abb0) at .../mysql-5.6.40/sql/sql_parse.cc:2853
#5  0x..... in mysql_parse (thd=thd@entry=0x5d0abb0, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7fe44c644690) at .../mysql-5.6.40/sql/sql_parse.cc:6453
#6  0x..... in dispatch_command (command=<optimized out>, thd=0x5d0abb0, packet=0x5d0def1 "show slave status", packet_length=17) at .../mysql-5.6.40/sql/sql_parse.cc:1374

通过上面的信息可知，卡住是因为 show slave status 在获取某种 mutex 锁 的时候被阻塞住所导致的。我们根据这个结论准备在测试环境中模拟和分析。

测试环境

客户的 MySQL 版本比较旧，所以自己准备了 MySQL 5.7.41 的 debug 环境。后续的测试分析都基于该版本，其他版本可能存在差异，但分析过程类似。

源码分析

执行 show slave status 时需要哪些 mutex 锁？我们去源码中看看 show slave status 的执行逻辑。

当我们在客户端执行 show slave status 命令后，经过一系列兜兜转转，会来到 mysql_execute_command 函数，进入 SQLCOM_SHOW_SLAVE_STAT 分支，对应文件为 mysql-5.7.41\sql\sql_parse.cc。

case SQLCOM_SHOW_SLAVE_STAT:
 {
   /* Accept one of two privileges */
   if (check_global_access(thd, SUPER_ACL | REPL_CLIENT_ACL))
     goto error;
   res= show_slave_status_cmd(thd);
   break;
 }

show_slave_status_cmd 函数是 show slave status 命令的入口，可以看出会涉及 channel_map 锁，对应文件为 mysql-5.7.41\sql\rpl_slave.cc。

bool show_slave_status_cmd(THD *thd)
{
  Master_info *mi= 0;
  LEX *lex= thd->lex;
  bool res;
  ......
  channel_map.rdlock();
  if (!lex->mi.for_channel)
    res= show_slave_status(thd);
  else
  {
    ......
    res= show_slave_status(thd, mi);
  }
  channel_map.unlock();
  ......
}

show_slave_status 函数负责执行 show slave status 语句，可以看出涉及 global_sid_lock 锁，对应文件为 mysql-5.7.41\sql\rpl_slave.cc。

bool show_slave_status(THD* thd, Master_info* mi)
{
  ......
  if (mi != NULL)
  {
    global_sid_lock->wrlock();
    ......
    global_sid_lock->unlock();
  }
  ......
  show_slave_status_metadata(field_list, io_gtid_set_size, sql_gtid_set_size);
  ......
  if (mi != NULL && mi->host[0])
  {
    if (show_slave_status_send_data(thd, mi,io_gtid_set_buffer, sql_gtid_set_buffer))
     ......
}

show_slave_status_send_data 函数将数据发送到 Master_info 的客户端，这部分涉及的锁相对较多，对应文件为 mysql-5.7.41\sql\rpl_slave.cc。

bool show_slave_status_send_data(THD *thd, Master_info *mi,char* io_gtid_set_buffer,char* sql_gtid_set_buffer)
{
  ......
  mysql_mutex_lock(&mi->info_thd_lock);
  ......
  mysql_mutex_unlock(&mi->info_thd_lock);
 
  mysql_mutex_lock(&mi->rli->info_thd_lock);
  ......
  mysql_mutex_unlock(&mi->rli->info_thd_lock);
 
  mysql_mutex_lock(&mi->data_lock);
  mysql_mutex_lock(&mi->rli->data_lock);
  mysql_mutex_lock(&mi->err_lock);
  mysql_mutex_lock(&mi->rli->err_lock);
  ......
  mysql_mutex_unlock(&mi->rli->err_lock);
  mysql_mutex_unlock(&mi->err_lock);
  mysql_mutex_unlock(&mi->rli->data_lock);
  mysql_mutex_unlock(&mi->data_lock);
}

show_master_status 函数负责执行 show master status 语句，可以看出涉及 global_sid_lock 锁，对应文件为 mysql-5.7.41\sql\rpl_slave.cc。

bool show_master_status(THD* thd)
{
  ......
  global_sid_lock->wrlock();
  ......
  global_sid_lock->unlock();
  ......
}

关于主从复制中的 mutex 锁 的功能及涉及到该锁的大部分操作，官方还是很贴心的给出了详细的解释，就不一一赘述了。对应文件为 mysql-5.7.41\sql\rpl_slave.h（略）。

3模拟场景

直接模拟 show slave status 卡住的场景不太容易，但是通过 debug+断点调试可以轻松实现。

从前文源码分析可知，show slave status 命令和 show master status 命令执行过程中都涉及到获取 global_sid_lock 锁，因此可以在 show master status 命令对应的函数中获取 global_sid_lock 锁 （此时还没释放的中间位置设置断点），然后执行 show slave status 命令时获取 global_sid_lock 锁 便会被阻塞。另外，可以同步在释放 global_sid_lock 锁 函数结束之前设置断点，形成对比。详细流程及步骤如下：

源码编译 debug 模式，启动 MySQL 服务，并启动两个会话。

#查看 MySQL 进程
[root@localhost ~]# ps -ef|grep mysql
root     14949 14919  0 23:13 pts/3    00:00:00 grep --color=auto mysql
mysql    31658     1  0 06:52 ?        00:01:14 /root/mysql-5.7.41/build/sql/mysqld --defaults-file=/etc/my.cnf --user=mysql

#会话 A
mysql> show processlist;
+----+------+-----------+------+---------+------+----------+------------------+
| Id | User | Host      | db   | Command | Time | State    | Info             |
+----+------+-----------+------+---------+------+----------+------------------+
|  4 | root | localhost | NULL | Query   |    0 | starting | show processlist |
|  5 | root | localhost | NULL | Sleep   |    9 |          | NULL             |
+----+------+-----------+------+---------+------+----------+------------------+
2 rows in set (0.00 sec)
  
#会话 B
mysql> show processlist;
+----+------+-----------+------+---------+------+----------+------------------+
| Id | User | Host      | db   | Command | Time | State    | Info             |
+----+------+-----------+------+---------+------+----------+------------------+
|  4 | root | localhost | NULL | Sleep   |  154 |          | NULL             |
|  5 | root | localhost | NULL | Query   |    0 | starting | show processlist |
+----+------+-----------+------+---------+------+----------+------------------+
2 rows in set (0.00 sec)
 
#查看 thread 表
mysql> select thread_id,processlist_id ,thread_os_id, name from performance_schema.threads where  name="thread/sql/one_connection";
+-----------+----------------+--------------+---------------------------+
| thread_id | processlist_id | thread_os_id | name                      |
+-----------+----------------+--------------+---------------------------+
|        30 |              4 |        16055 | thread/sql/one_connection |
|        31 |              5 |        16090 | thread/sql/one_connection |
+-----------+----------------+--------------+---------------------------+
2 rows in set (0.00 sec)

gdb 关联 MySQL 进程并设置断点。

#关联 MySQL 进程
Type "apropos word" to search for commands related to "word".
(gdb) show non-stop
Controlling the inferior in non-stop mode is off.
(gdb) set non-stop on
(gdb) show non-stop
Controlling the inferior in non-stop mode is on.
(gdb) attach 31658
Attaching to process 31658
  
#查看相关线程
(gdb) info threads
  Id   Target Id         Frame
* 1    Thread 0x2b0ca2618480 (LWP 31658) "mysqld" 0x00002b0ca4113ddd in poll () from /lib64/libc.so.6
  ......
  31   Thread 0x2b0caff6a700 (LWP 16055) "mysqld" (running)
  32   Thread 0x2b0caff28700 (LWP 16090) "mysqld" (running)
 
 
#切换到指定线程，对应会话 A
(gdb) t 31
[Switching to thread 31 (Thread 0x2b0caff6a700 (LWP 16055))](running)
  
#设置断点，持有锁而不释放
(gdb) b rpl_master.cc:647
Breakpoint 1 at 0x181a565: file /root/mysql-5.7.41/sql/rpl_master.cc, line 647.
#设置断点，释放锁
(gdb) b rpl_master.cc:649
Breakpoint 2 at 0x181a577: file /root/mysql-5.7.41/sql/rpl_master.cc, line 649.
#查看断点
(gdb) info breakpoints
Num     Type           Disp Enb Address            What
1       breakpoint     keep y   0x000000000181a565 in show_master_status(THD*) at /root/mysql-5.7.41/sql/rpl_master.cc:647
2       breakpoint     keep y   0x000000000181a577 in show_master_status(THD*) at /root/mysql-5.7.41/sql/rpl_master.cc:649

会话 B 执行 show slave status 命令。

#结果很快返回，不会被阻塞
mysql> show slave status;
Empty set (0.00 sec)

先在会话 A 执行 show master status 命令，然后在会话 B 执行 show slave status 命令。

#会话 A 执行 "show master status" 命令卡住
mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2024-08-02 23:55:02 |
+---------------------+
1 row in set (0.00 sec)
 
mysql> show master status;
 
 
#会话 B 执行 "show slave status" 命令卡住
mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2024-08-02 23:55:18 |
+---------------------+
1 row in set (0.00 sec)
 
mysql> show slave status;
 
 
  
#会话 A 触发断点一
Thread 31 "mysqld" hit Breakpoint 1, show_master_status (thd=0x2b0e040009a0) at /root/mysql-5.7.41/sql/rpl_master.cc:648
648       global_sid_lock->unlock();
 
Num     Type           Disp Enb Address            What
1       breakpoint     keep y   0x000000000181a565 in show_master_status(THD*) at /root/mysql-5.7.41/sql/rpl_master.cc:647
        breakpoint already hit 1 time
2       breakpoint     keep y   0x000000000181a577 in show_master_status(THD*) at /root/mysql-5.7.41/sql/rpl_master.cc:649

gdb 调试继续运行会话 A，观察会话 A 和会话 B 状态。

#继续运行，会话 A 触发断点二
(gdb) c
Continuing.
 
Thread 31 "mysqld" hit Breakpoint 2, show_master_status (thd=0x2b0e040009a0) at /root/mysql-5.7.41/sql/rpl_master.cc:650
650       field_list.push_back(new Item_empty_string("File", FN_REFLEN));
 
 
#观察会话 A，"show master status"命令继续卡住
mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2024-08-02 23:55:02 |
+---------------------+
1 row in set (0.00 sec)
 
mysql> show master status;
 
#观察会话 B，"show slave status"命令返回
mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2024-08-02 23:55:18 |
+---------------------+
1 row in set (0.00 sec)
 
mysql> show slave status;
Empty set (4 min 13.76 sec)
 
 
#会话 B 继续执行 "show slave status" 命令都立即返回
mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2024-08-03 00:03:53 |
+---------------------+
1 row in set (0.00 sec)
 
mysql> show slave status;
Empty set (0.00 sec)
 
mysql> show slave status;
Empty set (0.00 sec)
 
#继续运行，观察会话 A，因为后面没有其他断点，所以成功返回
mysql> show master status;
+------------------+----------+--------------+------------------+-------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+------------------+----------+--------------+------------------+-------------------+
| mysql-bin.000044 |      154 |              |                  |                   |
+------------------+----------+--------------+------------------+-------------------+
1 row in set (9 min 56.99 sec)
 
mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2024-08-03 00:05:34 |
+---------------------+
1 row in set (0.00 sec)

注意：如果断点设置在 show master status 命令获取 global_sid_lock 锁 之前或者释放 global_sid_lock 锁 之后则无法阻塞 show slave status 命令。

4总结

通过代码和试验，对 show slave status 命令有了更清晰的了解。可能导致 show slave status 卡住的场景很多，例如前面的模拟测试，无法穷举。类似问题可以从以下方向进行排查:

执行 show slave status 过程中会需要获取 channel_map.rdlock()，global_sid_lock->wrlock，mi->data_lock 等相关 mutex 锁。如果此时这些锁中的一个或多个锁被其他线程持有，show slave status 就会阻塞。
当 show slave status 命令执行阻塞时，可以借助 pstack 工具和 performance_schema.threads （MySQL 5.7 之前的版本不支持 thread_os_id 字段）表保留当时信息，便于后期进行排查，分析 show slave status 命令阻塞的位置点。