在多实例场景下 MySQL Server hang 住,无法测试下去,原生版本不存在这个问题,而新版本上出现了这个问题,不禁心头一颤,心中不禁感到奇怪,还好现场环境还在,为排查问题提供了一个好的环境,随即便投入到紧张的问题排查过程当中。问题实例表现如下:

并发量为 384 的时候出现的问题;

MySQL 服务器无法执行事务相关的语句,即使简单的 select 语句也无法执行;

所有线程处于等待状态,无法 KILL。

现场环境的收集

首先,通过 pstack 工具获取当前问题实例的堆栈信息以便后面具体线程的查找 & 问题线程的定位:

mysql oom如何排查原因 mysql故障排查思路_MySQL

使用 pt-pmp 工具统计 hang.info 中的进程信息,如下:

mysql oom如何排查原因 mysql故障排查思路_MySQL死锁问题如何排查_02

mysql oom如何排查原因 mysql故障排查思路_数据_03

mysql oom如何排查原因 mysql故障排查思路_MySQL死锁问题如何排查_04

mysql oom如何排查原因 mysql故障排查思路_MySQL_05

mysql oom如何排查原因 mysql故障排查思路_MySQL死锁问题如何排查_06

mysql oom如何排查原因 mysql故障排查思路_堆栈_07

mysql oom如何排查原因 mysql故障排查思路_MySQL死锁问题如何排查_08

mysql oom如何排查原因 mysql故障排查思路_mysql oom如何排查原因_09

mysql oom如何排查原因 mysql故障排查思路_MySQL死锁问题如何排查_10

问题分析

从堆栈上可以看出,有这样几类线程:

等待进入 INNODB engine 层的用户线程,测试环境中 innodb_thread_concurrency=16, 当 INNODB 层中的活跃线程数目大于此值时则需要排队,所以会有大量的排队线程,这个参数的影响&作用本身就是一篇很不错的文章,由于篇幅有限,在此不做扩展,感兴趣者可以参考官方文档:https://dev.mysql.com/doc/refman/5.6/en/innodb-parameters.html#sysvar_innodb_thread_concurrency;

操作过程中需要写 redo log 的后台线程,主要包括 page cleaner 线程、异步 io threads等;

正在读取Page页面的 purge 线程 & 操作 change buffer 的 master thread;

大量的需要写 redo log 的用户线程。

从以上的分类不难看出,所有需要写 redo log 的线程都在等待 log_sys->mutex,那么这个保护 redo log buffer 的 mutex 被究竟被哪个线程获取了呢,因此,我们可以顺着这个线索进行问题排查,需要解决以下问题:

问题一:哪个线程获取了 log_sys->mutex ?

问题二:获取 log_sys->mutex 的线程为什么没有继续执行下去,是在等其它锁还是其它原因?

问题三:如果不是硬件问题,整个资源竟争的过程是如何的?

1、问题一:由表及里

在查找 log_sys->mutex 所属线程情况时,有两点可以帮助我们快速的定位到这个线程:

由于 log_sys->mutex 同时只能被同一个线程获得,所以在 pt-pmp 的信息输出中就可以排除线程数目大于1的线程;

此线程既然已经获取了 log_sys->mutex, 那就应该还是在写日志的过程中,因此重点可以查看写日志的逻辑,即包括:mtr_log_reserve_and_write 或 log_write_up_to 的堆栈。

顺着上面的思路很快的从 pstack 中找到了以下线程:

mysql oom如何排查原因 mysql故障排查思路_mysql oom如何排查原因_11

mysql oom如何排查原因 mysql故障排查思路_MySQL_12

mysql oom如何排查原因 mysql故障排查思路_堆栈_13

这里我们简单介绍一下MySQL写 redo log 的过程(省略undo & buffer pool 部分),当对数据进行修改时,MySQL 会首先对针对操作类型记录不同的 redo 日志,主要过程是:

记录操作前的数据,根据不同的类型生成不同的 redo 日志,redo 的类型可以参考文件:src/storage/innobase/include/mtr0mtr.h

记录操作之后的数据,对于不同的类型会包含不同的内容,具体可以参考函数:recv_parse_or_apply_log_rec_body();

写日志到 redo buffer,并将此次涉及到脏页的数据加入到 buffer_pool 的 flush list 链表中;

根据 innodb_flush_log_at_trx_commit 的值来判断在commit 的时候是否进行 sync 操作。

上面的堆栈则是写Redo后将脏页加到 flush list 过程中时 hang 住了,即此线程在获取了 log_sys->mutex 后,在获取 log_sys->log_flush_order_mutex 的过程中 hang 住了,而此时有大量的线程在等待该线程释放log_sys->mutex锁,问题一 已经有了答案,那么log_sys->log_flush_order_mutex 是个什么东东,它又被哪个占用了呢?

说明:

MySQL 的 buffer pool 维护了一个有序的脏页链表 (flush list according LSN order),这样在做 checkpoint & log_free_check 的过程中可以很快的定位到 redo log 需要推进的位置,在将脏页加入;

flush list 过程中需要对其上锁以保证 flush list 中 LSN 的有序性, 但是如果使用 log_sys->mutex,在并发量大的时候则会造成 log_sys->mutex 的 contention,进而引起性能问题,因此添加了另外一个 mutex 来保护脏页按 LSN 的有序性,代码说明如下:

mysql oom如何排查原因 mysql故障排查思路_MySQL_14

2、问题二:弹尽粮绝

在问题一的排查过程中我们确定了 log_sys->mutex 的所属线程, 这个线程在获得 log_sys->log_flush_order_mutex 的过程中 hang 住了,因此线程堆栈可以分以为下几类:

Thread 446, 获得 log_sys->mutex, 等待获取 log_sys->log_flush_order_mutex 以把脏页加入到 buffer_pool 的 flush list中;

需要获得 log_sys->mutex 以写日志或者读取日志信息的线程;

未知线程获得 log_sys->log_flush_order_mutex,在做其它事情的时候被 hang 住。