不知不觉，涉足云计算行业已经半年多了，在参与CDB项目的半年多时间，做了不少杂事，也积累了不少东西(主要是MySQL内核和云计算相关的)。开放平台加上公司内部数千款业务都在使用MySQL，几乎每天会遇到各种MySQL问题，各种MySQL的bug和使用问题，一直想把这些问题总结一下，但是由于平时太忙，一直没有时间。但时间一久，又怕这些放在电脑里的文档，会随光阴一样，消失的无影无踪。。。OK，有时间就写一下吧。就从今天遇到的一个MySQL bug开始吧。。。
1、问题描述
今天运维组的同事反映某业务的线上mysql实例出现无法连接的情况，机器CPU、磁盘IO负载都很正常，mysqld进程也在，就是连上没有反应。经过分析，发现mysqld出现了死锁，mysqld 90多个线程，大部分都在等待LOCK_open:
#1 0x00002b785655fa67 in _L_mutex_lock_1029 () from /lib64/libpthread.so.0
#2 0x00002b785655f9e7 in pthread_mutex_lock () from /lib64/libpthread.so.0
...
以前，常遇到table lock和innodb lock的死锁问题，前者可以通过kill connection解决，后者一般会引起事务回滚。这个死锁问题是第一次遇到，经过一番折腾，终于搞清楚了原因。。。
2、问题原因
在mysql中，LOCK_global_system_variables和LOCK_open这2个mutex在代码里面随处可见，今天遇到的这个死锁问题就是这两兄弟引起的。
从上面可以看到，线程29828持有LOCK_global_system_variables，线程14412持有LOCK_open。
下面看看这2个线程在做什么，先看线程29828吧：
#0 0x00002b78565636a8 in __lll_mutex_lock_wait () from /lib64/libpthread.so.0
#1 0x00002b785655fa67 in _L_mutex_lock_1029 () from /lib64/libpthread.so.0
#2 0x00002b785655f9e7 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3 0x000000000062baf1 in close_performance_schema_table (thd=0x2ab115613d30, backup=0x450ca380) at sql_base.cc:9158
#4 0x000000000067e59e in Log_to_csv_event_handler::activate_log (this=<value optimized out>, thd=0x2ab115613d30,
log_table_type=<value optimized out>) at log.cc:724
#5 0x0000000000682384 in LOGGER::activate_log_handler (this=0xcf2520, thd=0x2ab115613d30, log_type=<value optimized out>) at log.cc:1165
#6 0x0000000000607634 in sys_var_log_state::update (this=0xceec60, thd=0x2ab115613d30, var=0x2ab11532a7e0) at set_var.cc:2466
#7 0x00000000005fc955 in set_var::update (this=0x2ab11532a7e0, thd=0x2ab115613d30) at set_var.cc:3617
#8 0x0000000000606ac9 in sql_set_variables (thd=0x2ab115613d30, var_list=0x2ab115616118) at set_var.cc:3492
#9 0x00000000005f4474 in mysql_execute_command (thd=0x2ab115613d30) at sql_parse.cc:3553
#10 0x00000000005f9c98 in mysql_parse (thd=0x2ab115613d30, rawbuf=0x2ab11532a6a0 "set global slow_query_log=ON", length=28,
found_semicolon=0x450cc0f0) at sql_parse.cc:6068
线程(LWP)29828在close_performance_schema_table中的，等待mutex：
bool sys_var_log_state::update(THD *thd, set_var *var)
{
bool res;
if (this == &sys_var_log)
WARN_DEPRECATED(thd, "7.0", "@@log", "'@@general_log'");
else if (this == &sys_var_log_slow)
WARN_DEPRECATED(thd, "7.0", "@@log_slow_queries", "'@@slow_query_log'");
pthread_mutex_lock(&LOCK_global_system_variables);
if (!var->save_result.ulong_value)
{
logger.deactivate_log_handler(thd, log_type);
res= false;
}
else
res= logger.activate_log_handler(thd, log_type);
pthread_mutex_unlock(&LOCK_global_system_variables);
return res;
{
...
pthread_mutex_lock(&LOCK_open);
found_old_table= false;
/*
Note that we need to hold LOCK_open while changing the
open_tables list. Another thread may work on it.
(See: remove_table_from_cache(), mysql_wait_completed_table())
Closing a MERGE child before the parent would be fatal if the
other thread tries to abort the MERGE lock in between.
*/
while (thd->open_tables)
found_old_table|= close_thread_table(thd, &thd->open_tables);
if (found_old_table)
broadcast_refresh();
pthread_mutex_unlock(&LOCK_open);
...
再看线程14412在做什么：
#0 0x00002b78565636a8 in __lll_mutex_lock_wait () from /lib64/libpthread.so.0
#1 0x00002b785655fa67 in _L_mutex_lock_1029 () from /lib64/libpthread.so.0
#2 0x00002b785655f9e7 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3 0x000000000075bf12 in intern_sys_var_ptr (thd=0x2ab1155350f0, offset=0, global_lock=true) at sql_plugin.cc:2389
#4 0x00000000007825d8 in check_trx_exists (thd=0x2ab1155350f0) at handler/ha_innodb.cc:1193
#5 0x0000000000784eaa in ha_innobase::info_low (this=0x3407f4d0, flag=26, called_from_analyze=false) at handler/ha_innodb.cc:1252
#6 0x0000000000788e52 in ha_innobase::open (this=0x3407f4d0, name=0x2ab1155ff118 "./dreampool_love/uid_space_mapping_39",
mode=<value optimized out>, test_if_locked=<value optimized out>) at handler/ha_innodb.cc:2980
#7 0x00000000006d565f in handler::ha_open (this=0xcea760, table_arg=<value optimized out>,
name=0x2ab1155ff118 "./dreampool_love/uid_space_mapping_39", mode=2, test_if_locked=13543264) at handler.cc:2094
#8 0x000000000063518a in open_table_from_share (thd=0x2ab1155350f0, share=0x2ab1155fed90, alias=<value optimized out>, db_stat=0,
prgflag=<value optimized out>, ha_open_flags=0, outparam=0x33ff9290, is_create_table=false) at table.cc:1907
#9 0x000000000062ef88 in open_unireg_entry (thd=0x2ab1155350f0, entry=0x33ff9290, table_list=0x341df978,
alias=0x341df960 "uid_space_mapping_39", cache_key=0x44e56d30 "dreampool_love", cache_key_length=36, mem_root=0x44e56f30, flags=0)
at sql_base.cc:3932
#10 0x0000000000630037 in open_table (thd=0x2ab1155350f0, table_list=0x341df978, mem_root=0x44e56f30, refresh=0x44e56f8f, flags=0)
at sql_base.cc:2931
#11 0x0000000000630c77 in open_tables (thd=0x2ab1155350f0, start=0x44e56fd8, counter=0x44e56fe8, flags=0) at sql_base.cc:4619
#12 0x0000000000630ea0 in open_and_lock_tables_derived (thd=0x2ab1155350f0, tables=0x341df978, derived=true) at sql_base.cc:5037
#13 0x00000000005f13aa in execute_sqlcom_select (thd=0x2ab1155350f0, all_tables=0x341df978) at mysql_priv.h:1523
#14 0x00000000005f4732 in mysql_execute_command (thd=0x2ab1155350f0) at sql_parse.cc:2293
#15 0x00000000005f9c98 in mysql_parse (thd=0x2ab1155350f0,
rawbuf=0x341df700 "select * from xxx", length=87,
found_semicolon=0x44e590f0) at sql_parse.cc:6068
线程14412也在intern_sys_var_ptr中等待mutex：
TABLE *open_table(THD *thd, TABLE_LIST *table_list, MEM_ROOT *mem_root,
bool *refresh, uint flags)
{
...
VOID(pthread_mutex_lock(&LOCK_open)); //2727
...
error= open_unireg_entry(thd, table, table_list, alias, key, key_length, mem_root, (flags & OPEN_VIEW_NO_PARSE)); //2930
{
...
if (global_lock)
pthread_mutex_lock(&LOCK_global_system_variables);
...
}
线程29828持有LOCK_global_system_variables，请求LOCK_open；
线程14412持有LOCK_open，请求LOCK_global_system_variables；导致系统发生死锁。
3、总结
sys_var_log_state::update函数在持有LOCK_global_system_variables的情况去申请LOCK_open是不科学的做法，因为LOCK_open在MySQL用得如此频繁，这种嵌套使用，很容易引起死锁，导致系统停止响应。其实，问题的根本原因在于Log_to_csv_event_handler::activate_log在调用open_performance_schema_table打开slow log table后，为什么又调用close_performance_schema_table关闭slow log table，这不是闲得蛋疼吗？有待进一步思考。。。
这显然是MySQL的bug。搜了一下buglist，似乎还没有发现该bug相关的report。
ps:该bug仅限于mysql 5.1.54，其它版本是否存在，请参阅source code。
作者：MrDB
出处：http://www.cnblogs.com/hustcat/
本文版权归作者和博客园共有，欢迎转载，但未经作者同意必须保留此段声明，且在文章页面明显位置给出原文连接，否则保留追究法律责任的权利。