不知不觉，涉足云计算行业已经半年多了，在参与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

出处：

本文版权归作者和博客园共有，欢迎转载，但未经作者同意必须保留此段声明，且在文章页面明显位置给出原文连接，否则保留追究法律责任的权利。