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

淡淡的烟草味﹌ 2022-09-30 10:55 341阅读 0赞

**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

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

发表评论取消回复

还没有评论，来说两句吧...

相关阅读

相关 MySQL备份恢复出现问题：故障排查流程

相关 MySQL日志分析：故障排查实例

相关 MySQL 连接故障排查

相关 Oracle 监听hang住

相关 MySQL 执行DDL语句 hang住了怎么办?

相关 MySQL客户端连接登入hang住原因分析

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

相关 ogg ddl marker_setup.sql hang住问题

相关 datastage作业hang住

相关网络故障一般排查操作