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

由问题二的分析过程可以得出某线程在 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 及之前的版本都有此问题.

文章出处：DBAplus社群

（编辑：ASP站长网）