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
————————————————
版权声明：本文为CSDN博主「slwang001」的原创文章，遵循CC 4.0 BY-SA版权协议，转载请附上原文出处链接及本声明。
原文链接：https://blog.csdn.net/slwang001/article/details/64443066
posted on
