一个罕见的MySQL redo死锁问题排查及解决过程

作者：张青林，腾讯云布道师、MySQL架构师，隶属腾讯TEG-基础架构部-CDB内核开发团队，专注于MySQL内核研发&相关架构工作，有着服务多个10W级QPS客户的数据库优化及稳定性维护经验。腾讯云数据库团队：继承腾讯数据库团队十多年海量存储的内部数据库运营和运维经验，推出一系列高性能关系型、分布式、文档型和缓存类数据库产品，并提供高可用性、自动化运维和易维护的云数据库综合解决方案。

创新互联不只是一家网站建设的网络公司；我们对营销、技术、服务都有自己独特见解，公司采取“创意+综合+营销”一体化的方式为您提供更专业的服务！我们经历的每一步也许不一定是最完美的，但每一步都有值得深思的意义。我们珍视每一份信任，关注我们的成都网站建设、网站制作质量和服务品质，在得到用户满意的同时，也能得到同行业的专业认可，能够为行业创新发展助力。未来将继续专注于技术创新，服务升级，满足企业一站式网络营销推广需求，让再小的高端网站设计也能产生价值！

问题背景

周一上班，首先向同事了解了一下上周的测试情况，被告知在多实例场景下 MySQL Server hang 住，无法测试下去，原生版本不存在这个问题，而新版本上出现了这个问题，不禁心头一颤，心中不禁感到奇怪，还好现场环境还在，为排查问题提供了一个好的环境，随即便投入到紧张的问题排查过程当中。问题实例表现如下：

• 并发量为 384 的时候出现的问题;
• MySQL 服务器无法执行事务相关的语句，即使简单的 select 语句也无法执行;
• 所有线程处于等待状态，无法 KILL。

现场环境的收集

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

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

问题分析

从堆栈上可以看出，有这样几类线程：

• 等待进入 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写 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 的有序性，代码说明如下：

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 住。

因此，问题的关键是找到哪个线程获取了 log_sys->log_flush_order_mutex。

为了找到相关的线程做了以下操作：

• 查找获取 log_sys->log_flush_order_mutex 的地方;

• 结合现有 pstack 中的线程信息，仔细查看上述查找结果中的相关代码，发现基本没有线程获得 log_sys->log_flush_order_mutex;
• gdb 进入 MySQL Server, 将 log_sys->log_flush_order_mutex 打印出来，发现 {waiters=1; lock_word= 0}!!!，即 Thread 446 在等待一个空闲的 mutex，而这个Mutex也确实被等待，由于我们的版本为 Release 版本，所以很多有用的信息没有办法得到，而若用 debug 版本跑则很难重现问题，log_flush_order_mutex 的定义如下：

由以上的分析可以得出 问题二 的答案：

• 只有两个线程和log_sys->log_flush_order_mutex有关，其中一个是 Thread 446 线程， 另外一个则是最近一次调用 log_flush_order_mutex_exit() 的线程;
• 现有线程中某个线程在释放log_sys->log_flush_order_mutex的过程中没有唤醒 Thread 446，导致Thread 446 hang 并造成其它线程不能获得 log_sys->mutex，进而造成实例不可用;
• log_sys->log_flush_order_mutex 没有被任何线程获得。

3、问题三：绝处逢生

由问题二的分析过程可知 log_sys->log_flush_order_mutex 没有被任何线程获得，可是为什么 Thread 446 没有被唤醒呢，信号丢失还是程序问题?如果是信号丢失，为什么可以稳定复现?官方的bug list 列表中是没有类似的 Bug的，搜了一下社区，发现可用信息很少，这个时候分析好像陷入了死胡同，心里压力开始无形中变大……好像没有办法，但是任何问题都是有原因的，找到了原因，也就是有解的了……再一次将注意力移到了 Thread 446 的堆栈中，然后查看了函数：

由问题二的分析过程可以得出某线程在 log_flush_order_mutex_exit 的退出过程没有将 Thread 446 唤醒，那么就顺着这个函数找，看它如何唤醒其它本程的，在没有办法的时候也只有这样一步一步的分析代码，希望有些收获，随着函数调用的不断深入，将目光定在了 mutex_exit_func 上, 函数中的注释引起了我的注意：

从上面的注释中可以得到两点信息：

• 由于 memory barrier 的存在，mutex_get_waiters & mutex_reset_lock_word 的调用顺序可能与执行顺序相反，这种情况下会引起 hang 问题;
• 专门写了一个函数 sync_arr_wake_threads_if_sema_free() 来解决上述问题。

由上面的注释可以看到，并不是信号丢失，而是多线程 memory barrier 的存在可能会造成指令执行的顺序的异常，这种问题确定存在，但既然有sync_arr_wake_threads_if_sema_free() 规避这个问题，为什么还会存在 hang 呢?有了这个线索，瞬间感觉有了些盼头……经过查找 sync_arr_wake_threads_if_sema_free 只在 srv_error_monitor_thread 有调用，这个线程是专门对 MySQL 内部异常情况进行监控并打印出 error 信息的线程，臭名昭著的 600S 自杀案也是它的杰作， 那么问题来了：

• 机器周末都在 hang 着，为什么没有检测到异常并 abort 呢?
• 既然 sync_arr_wake_threads_if_sema_free 可以唤醒，为什么没有唤醒呢?

顺着这个思路，查看了pstack 中 srv_error_monitor_thread 的堆栈，可以发现此线程在获取 log_sys->mutex 的时候hang 住了，因此无法执行sync_arr_wake_threads_if_sema_free() & 常归的异常检查，正好回答了上面的问题，详细堆栈如下：

经过上面的分析问题越来越明朗了，过程可以简单的归结为：

• Thread 446 获得 log_sys->mutex, 但是在等待 log_sys->log_flush_order_mutex 的过程中没有被唤醒;
• Thread XXX 在释放 log_sys->log_flush_order_mutex 的过程中出现了 memory barrier 问题，没有唤醒 Thread 446;
• Thread 470 获得 log_sys->mutex 时被 hang 住，导致无法执行 sync_arr_wake_threads_if_sema_free(), 导致了整个实例的 hang 住;
• Thread 470 需要获得 Thread 446 的 log_sys->mutex， 而 Thread 446 需要被 Thread 470 唤醒才会释放 log_sys->mutex;

结合 log_sys->log_flush_order_mutex 的状态信息，实例 hang 住的整个过程如下：

关于 Memory barrier 的介绍可以参考 ：https://en.wikipedia.org/wiki/Memory_barrier

http://name5566.com/4535.html

问题解决

既然知道了问题产生的原因，那么问题也就可以顺利解决了，有两种方法：

• 直接移除 log_get_lsn 在此处的判断，本身就是开发人员加的一些判断信息，为了定位 LSN 的异常而写的，用到的时候也Crash了，用处不大;
• 保留判断，将 log_get_lsn 修改为 log_peek_lsn, 后者会首先进行 try_lock，当发现上锁失败的时候会直接返回，而不进行判断，这种方法较优雅些;
• 经过修改之后的版本在测试过程中没有没有再复现此问题。

问题扩展

虽然问题解决了，但官方版本中肯定存在着这个问题，为什么 buglist 没有找到相关信息呢，于是在查看了***代码，发现这个问题已经修复，修复方法为上面列的第二种方法，详细的 commit message 信息如下：

bug影响范围：MySQL 5.6.28 及之前的版本都有此问题。

分享名称：一个罕见的MySQL redo死锁问题排查及解决过程
本文地址：http://www.shufengxianlan.com/qtweb/news0/271600.html

网站建设、网络推广公司-创新互联，是专注品牌与效果的网站制作，网络营销seo公司；服务项目有等

广告

声明：本网站发布的内容（图片、视频和文字）以用户投稿、用户转载内容为主，如果涉及侵权请尽快告知，我们将会在第一时间删除。文章观点不代表本网站立场，如需处理请联系客服。电话：028-86922220；邮箱：631063699@qq.com。内容未经允许不得转载，或转载时需注明来源： 创新互联