MySQL所有操作hang住问题的故障排查

1.   系统环境

CentOS release 6.7

mysql社区版MySQL-5.5.24（源码编译安装）

 

 

2.   故障简述

首先收到故障告警，所有的监控无法读取到数据。无法正常连接数据库。

 

3.   故障排查

如下过程是在开发环境复现了故障后，对故障排查具体过程的模拟。

 

3.1. 尝试登陆数据库

发现登陆发生hang住的情况，无法正常连接。无任何提示信息报出。

shell>mysql-h192.168.150.21 -P50001 -uabc -pabc
 
shell>mysql  -S /var/lib/mysql/mysql.sock  -uabc -pabc
 

3.2. 查看错误日志

错误日志完全正常，无任何错误日志报出。

 

3.3. 使用pstack和gdb

在使用常规手段无法读取数据库的基本信息和错误信息的情况下，我们考虑使用linux环境下的进程调试工具pstack和gdb。其中pstack可以打印出指定进程的全部堆栈信息，gdb可以调试进程，查看进程的具体堆栈信息、内存使用情况等一系列具体信息。

 

3.3.1. 使用pstack

使用pstack工具查看进程内各个线程的堆栈信息。执行命令：

shell>pstack  <mysqld pid>  >  pstack.log
 

将堆栈日志存放到pstack.log文件中，分析堆栈日志的内容。发现存在很多线程处于等待线程互斥量mutex的状态，并且等待的mutex是两个不同的mutex，猜测是源码内存在bug，造成了进程死锁：

 

Thread 2 (Thread0x7f8df41f8700 (LWP 13789)):
#0  0x00007f8df8fea2e4 in __lll_lock_wait () from/lib64/libpthread.so.0
#1  0x00007f8df8fe5588 in_L_lock_854 () from/lib64/libpthread.so.0
#2  0x00007f8df8fe5457 in pthread_mutex_lock
() from/lib64/libpthread.so.0
#3  0x00000000008d36d6 in safe_mutex_lock ()
#4  0x00000000007fa28b in inline_mysql_mutex_lock()
#5  0x000000000080364d inMYSQL_BIN_LOG::reset_logs(THD*) ()
#6  0x000000000061d211 in reset_master(THD*) ()
#7  0x00000000006fa4ce inreload_acl_and_cache(THD*, unsigned long, TABLE_LIST*, int*) ()
#8  0x00000000005f7c55 in mysql_execute_command(THD*)()
 

Thread 3 (Thread0x7f8df4239700 (LWP 13070)):
#0  0x00007f8df8fea2e4 in __lll_lock_wait () from/lib64/libpthread.so.0
#1  0x00007f8df8fe55be in _L_lock_995 () from/lib64/libpthread.so.0
#2  0x00007f8df8fe5526 in pthread_mutex_lock () from/lib64/libpthread.so.0
#3  0x00000000008d36d6 in safe_mutex_lock ()
#4  0x00000000006187e7 in inline_mysql_mutex_lock()
#5  0x000000000061981b in log_in_use(char const*)()
#6  0x0000000000804200 inMYSQL_BIN_LOG::purge_logs(char const*, bool, bool, bool, unsigned long long*)()
#7  0x0000000000619a27 in purge_master_logs(THD*,char const*) ()
#8  0x00000000005f35f0 inmysql_execute_command(THD*) ()
其中线程2和线程3分别在等待不同的mutex。

 

Thread N (Thread0x7f8df427a700 (LWP 7759)):
#0  0x00007f8df8fea2e4 in __lll_lock_wait () from/lib64/libpthread.so.0
#1  0x00007f8df8fe55be in _L_lock_995 () from/lib64/libpthread.so.0
#2  0x00007f8df8fe5526 in pthread_mutex_lock () from/lib64/libpthread.so.0
#3  0x00000000008d36d6 in safe_mutex_lock ()
#4  0x0000000000651e42 in inline_mysql_mutex_lock()
#5  0x0000000000657368 inmysqld_list_processes(THD*, char const*, bool) ()
#6  0x00000000005f5f2a inmysql_execute_command(THD*) ()
而其他新连接或者已经连接无应答的进程，也在等待其中的一个mutex。

 

3.3.2. 使用gdb查看具体信息

执行如下命令attach到mysqld进程，查看当前线程堆栈的具体情况。

shell>gdb -p  <mysqld pid> 
 

执行命令info thread查看线程的具体信息，发现很多线程均在等待锁信息，通过上面描述的pstack日志信息，我们知道线程2和线程3存在等待不同锁的行为且可疑性比较高。

(gdb) info thread
  M Thread 0x7f8df784a700 (LWP 7185)  0x00007f8df8ddb614 in ?? () from/lib64/libaio.so.1
  ……
  N Thread 0x7f8de251b700 (LWP 7365)  pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:239
  ……
  4 Thread 0x7f8df427a700 (LWP 7759)  __lll_lock_wait () at../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
  3 Thread 0x7f8df4239700 (LWP 13070)  __lll_lock_wait ()
at../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
  2 Thread 0x7f8df41f8700 (LWP 13789)  __lll_lock_wait ()
at../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
* 1 Thread 0x7f8df93fd720(LWP 7141)  __lll_lock_wait () at../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
 

 

切换到线程2查看，线程在等待的mutex为LOCK_index。

(gdb) thread 2
[Switching to thread 2(Thread 0x7f8df41f8700 (LWP 13789))]#0 __lll_lock_wait ()
    at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
136     2:     movl    %edx, %eax
 
(gdb) bt
……
#4  0x00000000007fa28b in inline_mysql_mutex_lock(that=0x12cc8d0,

    src_file=0xc10968"/..../mysql-5.5.24/sql/log.cc",src_line=3425)
    at/....../mysql-5.5.24/include/mysql/psi/mysql_thread.h:615
#5  0x000000000080364d in MYSQL_BIN_LOG::reset_logs(this=0x12cc400, thd=0x21d1ed0)
at /....../mysql-5.5.24/sql/log.cc:3425
……
 
(gdb) frame 5
#5  0x000000000080364d inMYSQL_BIN_LOG::reset_logs (this=0x12cc400, thd=0x21d1ed0)
    at/....../mysql-src/mysql-5.5.24/sql/log.cc:3425
3425      mysql_mutex_lock(&LOCK_index);
 

切换到线程3查看，线程在等待的mutex为LOCK_thread_count。

(gdb) thread 3
[Switching to thread 3(Thread 0x7f8df4239700 (LWP 13070))]#0 __lll_lock_wait ()
    at../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
136     2:     movl    %edx, %eax
 
(gdb) bt
……
#4  0x00000000006187e7 in inline_mysql_mutex_lock(that=0x12b1500,

    src_file=0xb86c30"/....../mysql-src/mysql-5.5.24/sql/sql_repl.cc",src_line=254)
    at/....../mysql-src/mysql-5.5.24/include/mysql/psi/mysql_thread.h:615
#5  0x000000000061981b in log_in_use (log_name=0x7f8df4236c60"./my_log.000001")
at /....../mysql-src/mysql-5.5.24/sql/sql_repl.cc:254
……
#7  0x0000000000619a27 in purge_master_logs (thd=0x21ca8f0,to_log=0x7f8dd0004cf8 "my_log.000004")
    at /....../mysql-src/mysql-5.5.24/sql/sql_repl.cc:311
……
(gdb) frame 5
#5  0x000000000061981b in log_in_use(log_name=0x7f8df4236c60 "./my_log.000001")
    at/....../mysql-src/mysql-5.5.24/sql/sql_repl.cc:254
254       mysql_mutex_lock(&LOCK_thread_count);
 

由此猜测，是源码中由于存在LOCK_index和LOCK_thread_count相互等待的BUG，导致两个mutex均未被释放，发生死锁情况，其它需要获得锁的操作均发生一致等待的情况（即发生hang住）。

 

3.4. 查看源码

根据gdb调试中线程2和线程3的信息，查看命令purgebinlog和reset master对应的源码。查看发现两个命令对于LOCK_thread_count和LOCK_index调用顺序是不同的。导致同时执行时会发生相互等待，发生死锁的情况。

 

dispatch_command
| purge_master_logs
|  | MYSQL_BIN_LOG::purge_logs
|     | mysql_mutex_lock(&LOCK_index);   
|     | log_in_use
|         | mysql_mutex_lock(&LOCK_thread_count);
|
| reload_acl_and_cache
|  | reset_master
|     | MYSQL_BIN_LOG::reset_logs
|        | mysql_mutex_lock(&LOCK_thread_count);
|        | mysql_mutex_lock(&LOCK_index);
 

4.   故障解决

同时执行了purge binlog和reset master命令，会小概率导致了如上问题的产生。

 

在我们分析源码的过程中，同时发现，设置了参数expir_logs_days后，在binlog发生切换时（当前binlog写满或者执行flush logs命令），也会走到发生死锁的代码分支，即如果同时执行reset master命令，也会发生死锁的情况。

 

在查看官方修复后，发现该bug已经修复。

 

该bug由官方在修复另一问题时同时修复，在版本5.5.39时修复。github上的Bug描述和修复细节为以下:
https://github.com/mysql/mysql-server/commit/33f15dc7acf817e1e99203734d3e4b16b50fcc17