本文内容遵从CC版权协议, 可以随意转载, 但必须以超链接形式标明文章原始出处和作者信息及版权声明网址: http://www.penglixun.com/tech/database/slave_sql_locked_bug.html 今天做一批备机加主键的工作时,意外发现,如果有一个线程阻塞了Slave SQL 线程应

本文内容遵从CC版权协议, 可以随意转载, 但必须以超链接形式标明文章原始出处和作者信息及版权声明网址: http://www.penglixun.com/tech/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_lockLOCK_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 }

09-13 19:06