P.Linux Laboratory

本文内容遵从CC版权协议, 可以随意转载, 但必须以超链接形式标明文章原始出处和作者信息及版权声明
网址: http://www.penglixun.com/database/slave_sql_locked_bug.html

今天做一批备机加主键的工作时，意外发现，如果有一个线程阻塞了Slave SQL线程应用日志，导致Slave SQL在Locked状态，再试图执行Slave Stop命令时，必定导致show slave status/master status等语句执行Hang死。
解决方法是只能等待锁定Slave SQL的线程结束，或者重启数据库，还没试出其他方法可以解决。已经在MySQL 5.0.68、5.1.30/34/40上重现。
搜索了Bug库，确实找到了这个bug，http://bugs.mysql.com/bug.php?id=56676，至少在5.1.50之前都会有这个问题。

查看了源码，主要是由于mi->run_lock和LOCK_active_mi两个锁导致的问题。
slave的运行流程是 start_slave_thread函数创建handler_slave_sql线程去轮询日志，handler_slave_sql调用exec_relay_log_event去应用日志事件，exec_relay_log_event又调用apply_event_and_update_pos来具体读取一个日志事件应用日志到存储引擎并更新relay-log的pos信息，最后根据读取的日志类型，调用不同类重载的XXX_log_event::do_apply_event去真正使用解出来的日志。

导致Hang住的原因是这样的：
slave_sql一旦启动成功，就会持有mi->run_lock锁，mi是Master_info的实例，记录主机信息，就是master.info的内容，mi->run_lock被持有表示mi的Slave正在运行（mi定义为Master_info *，注释里也说了，Multi Master写完后，mi是个数组，可以有每个Master分别持有锁，所以MySQL也在做这个事了），由于目前只支持单Master，所以mi的锁是全局的，即LOCK_active_mi。当一条SQL被Locked的时候，Slave SQL持有mi->run_lock，cond_wait等待不到继续进行的条件，于是运行不到if (!sql_slave_killed(thd,rli))这条语句。所以stop_slave发出kill无法被判断到，于是slave stop就Hang住了。由于stop slave持有LOCK_active_mi（关闭Slave需要保存master.info），而show slave status/show status都会先做pthread_mutex_lock(&LOCK_active_mi);因而全部堵住。
还有一个可能存在的风险，Relay_log_info类的tables_to_lock链表存了Slave要锁住的表，如果Slave不能及时继续，tables_to_lock链表就不能及时清理，会带来很多锁问题，可能引起大面积阻塞。上次有个故障，MySQL Hang死，很可能就是我们一个跳过复制错误的脚本show slave status和slave start/stop执行频率很高，突然切换主备需要建立大量连接的时候CPU上下文切换较多，释放LOCK_active_mi锁的速度就跟不上，另一些show slave status采集监控的脚本迅速阻塞，导致tables_to_lock链表不能及时释放，进而导致正常SQL执行被锁阻塞，由于变更量非常大，阻塞迅速蔓延，锁等待几乎把数据库Hang死。

所以我提醒各位，在Slave中有长SQL或Locked的SQL执行时，除show processlist;外千万不要做show slave/master status以及slave stop等slave相关命令。

handler_slave_sql循环执行：
03058 while (!sql_slave_killed(thd,rli))
03059 {
03060 thd_proc_info(thd, “Reading event from the relay log”);
03061 DBUG_ASSERT(rli->sql_thd == thd);
03062 THD_CHECK_SENTRY(thd);
03063
03064 if (saved_skip && rli->slave_skip_counter == 0)
03065 {省略
03076 }
03077
03078 if (exec_relay_log_event(thd,rli))
03079 {
03080 DBUG_PRINT(“info”, (“exec_relay_log_event() failed”));
03081 // do not scare the user if SQL thread was simply killed or stopped
03082 if (!sql_slave_killed(thd,rli))
03083 {省略
03144 }
03145 goto err;
03146 }
03147 }

show slave status命令
07409 static int show_slave_running(THD *thd, SHOW_VAR *var, char *buff)
07410 {
07411 var->type= SHOW_MY_BOOL;
07412 pthread_mutex_lock(&LOCK_active_mi);
07413 var->value= buff;
07414 *((my_bool *)buff)= (my_bool) (active_mi &&
07415 active_mi->slave_running == MYSQL_SLAVE_RUN_CONNECT &&
07416 active_mi->rli.slave_running);
07417 pthread_mutex_unlock(&LOCK_active_mi);
07418 return 0;
07419 }

清除锁定表的clear_tables_to_lcok
01222 void Relay_log_info::clear_tables_to_lock()
01223 {
01224 while (tables_to_lock)
01225 {
01226 uchar* to_free= reinterpret_cast(tables_to_lock);
01227 if (tables_to_lock->m_tabledef_valid)
01228 {
01229 tables_to_lock->m_tabledef.table_def::~table_def();
01230 tables_to_lock->m_tabledef_valid= FALSE;
01231 }
01232 tables_to_lock=
01233 static_cast(tables_to_lock->next_global);
01234 tables_to_lock_count–;
01235 my_free(to_free, MYF(MY_WME));
01236 }
01237 DBUG_ASSERT(tables_to_lock == NULL && tables_to_lock_count == 0);
01238 }