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/
本文版權歸作者和博客園共有，歡迎轉載，但未經作者同意必須保留此段聲明，且在文章頁面明顯位置給出原文連接，否則保留追究法律責任的權利。