set global slow_query_log引起的MySQL死锁

不知不觉，涉足云计算行业已经半年多了，在参与CDB项目的半年多时间，做了不少杂事，也积累了不少东西(主要是MySQL内核和云计算相关的)。开放平台加上公司内部数千款业务都在使用MySQL，几乎每天会遇到各种MySQL问题，各种MySQL的bug和使用问题，一直想把这些问题总结一下，但是由于平时太忙，一直没有时间。但时间一久，又怕这些放在电脑里的文档，会随光阴一样，消失的无影无踪。。。OK，有时间就写一下吧。就从今天遇到的一个MySQL bug开始吧。。。

 

1、问题描述
今天运维组的同事反映某业务的线上mysql实例出现无法连接的情况，机器CPU、磁盘IO负载都很正常，mysqld进程也在，就是连上没有反应。经过分析，发现mysqld出现了死锁，mysqld 90多个线程，大部分都在等待LOCK_open:

   # 
  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 
  
... 
 

 

以前，常遇到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吧：

 

   Thread  
  14 (Thread  
  1158465856 (LWP  
  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;

}

 

void close_performance_schema_table(THD *thd, Open_tables_state *backup)
{
...
   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在做什么：

   Thread  
  33 (Thread  
  1155897664 (LWP  
  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

...

}

 

 

static uchar *intern_sys_var_ptr(THD* thd,  int offset,  bool global_lock)
{
...
     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/
本文版权归作者和博客园共有，欢迎转载，但未经作者同意必须保留此段声明，且在文章页面明显位置给出原文连接，否则保留追究法律责任的权利。