作者：张庆林，腾讯云布道师，MySQL架构师，隶属于腾讯TEG-基础设施部-CDB内核开发团队，专注于MySQL内核研发及相关架构工作，有经验服务多个10W级QPS客户的数据库优化和稳定性维护。腾讯云数据库团队：继承了十几年的内部数据库运维和海量存储运维经验，腾讯数据库团队推出了一系列高性能的关系型、分布式、文档型和缓存型数据库产品，并提供高可用自动化运维、易维护的云数据库综合解决方案。问题背景我星期一去上班。首先，我向同事询问了上周的测试情况。我被告知MySQLServer在多实例场景中挂起并且无法测试。原版本不存在此问题，新版本出现此问题。我心头一颤，不禁有些奇怪。好在现场环境还在，为排查问题提供了良好的环境，我才全身心投入到紧张的排查过程中。问题示例如下：并发为384时出现问题；MySQL服务器不能执行事务相关的语句，连简单的select语句都不能执行；所有线程都处于等待状态，不能被KILL。现场环境采集首先使用pstack工具获取当前问题实例的堆栈信息，以便后续查找具体线程&定位问题线程：使用pt-pmp工具统计hang.info中的进程信息，如下：可以从栈上分析问题可以看出有几种线程：等待进入INNODB引擎层的用户线程，测试环境下innodb_thread_concurrency=16，当活跃线程数为INNODB层大于这个值，需要排队，所以会有大量的排队线程，这个参数的影响&作用本身就是一篇很好的文章。由于篇幅有限，这里不做展开。有兴趣的可以参考官方文档：https://dev.mysql.com/doc/refman/5.6/en/innodb-parameters.html#sysvar_innodb_thread_concurrency；运行过程中需要写入redolog的后台线程，主要包括pagecleaner线程，异步io线程等；正在读取页面的清除线程和操作更改缓冲区的主线程；很多需要写重做日志的用户线程。从上面的分类不难看出，所有需要写redolog的线程都在等待log_sys->mutex，那么保护redologbuffer的mutex是哪个线程获取到了呢？因此，我们可以按照这条线索来解决问题为了排查问题，需要解决以下问题：问题1：哪个线程获取了log_sys->mutex？问题2：为什么获取了log_sys->mutex的线程没有继续执行？是在等待其他锁还是其他原因？问题三：如果不是硬件问题，资源竞争的全过程是怎样的？1、问题一：从表和里面查找log_sys->mutex的线程状态时，有两点可以帮助我们快速定位到这个线程：因为log_sys->mutex同时只能是由同一个线程获取，所以线程数大于1的线程可以排除在pt-pmp的信息输出中；由于这个线程已经拿到了log_sys->mutex，所以应该还在写日志的过程中。因此，重点可以查看写入日志的逻辑，即堆栈包括：mtr_log_reserve_and_write或log_write_up_to。顺着上面的思路，很快从pstack中找到了如下跟帖：这里简单介绍下MySQL写入redolog的过程（省略undo&bufferpool部分）。记录不同的redolog，主要过程是：记录操作前的数据，根据不同的类型生成不同的redolog，redo类型可以参考文件：src/storage/innobase/include/mtr0mtr.h记录操作后的数据操作，不同的类型会包含不同的内容。具体可以参考函数：recv_parse_or_apply_log_rec_body();将log写入redobuffer，并将脏页相关数据加入buffer_pool的flushlist列表；根据innodb_flush_log_at_trx_commit的值判断commit时是否进行sync操作。上面的栈是在写入Redo后将脏页添加到flush列表时挂掉的，即线程在获取log_sys->mutex后在获取log_sys->log_flush_order_mutex的过程中挂掉了，此时有大量线程在等待为线程释放log_sys->mutex锁。问题1已经回答了，那么log_sys->log_flush_order_mutex是什么，被哪一个占用了呢？说明：MySQL的bufferpool维护了一个脏页链表（flushlistadverrentlyLSNorder），这样在checkpoint&log_free_check的过程中，可以快速定位到需要pushredolog的位置，并且在将脏页添加到flushlist的过程中，需要对dirtypages进行加锁，以保证LSN在flushlist中的顺序，但是如果使用log_sys->mutex，会导致log_sys->mutex的争用并发量大，会造成性能问题，所以又加了一个mutex来保护脏页根据LSN的顺序，代码说明如下：2.问题2：弹尽粮绝。在问题1的调查过程中，我们确定了log_sys->mutex所属的线程。该线程在获取log_sys->log_flush_order_mutex的过程中挂掉了，所以线程栈可以分为以下几类：线程446，获取log_sys->mutex，等待获取log_sys->log_flush_order_mutex将脏页添加到flush列表缓冲池；需要获取log_sys->mutex写入日志或读取日志信息的线程；未知线程获取log_sys->log_flush_order_mutex，在做其他事情时被挂起。因此，问题的症结在于找到哪个线程获得了log_sys->log_flush_order_mutex。为了找到相关的线程，做了如下操作：找到log_sys->log_flush_order_mutex获取的地方；结合现有pstack中的线程信息，仔细查看上面搜索结果中的相关代码，发现基本没有线程获取log_sys->log_flush_order_mutex；gdb进入MySQLServer，打印出log_sys->log_flush_order_mutex，发现{waiters=1;lock_word=0}!!!，即Thread446在等待一个空闲的mutex，而这个Mutex确实在等待，因为我们的版本是Release版本，所以很多有用的信息得不到，难以复现如果您使用调试版本运行它，则会出现问题。log_flush_order_mutex的定义如下：从上面的分析可以得到问题2的答案：log_sys->log_flush_order_mutex相关的线程只有两个，一个是Thread446，另一个是调用log_flush_order_mutex_exit的线程（）上次;其中一个存在的线程在释放log_sys->log_flush_order_mutex的过程中没有唤醒Thread446，导致Thread446挂起，导致其他线程无法获取log_sys->mutex，导致实例不可用；log_sys->log_flush_order_mutex不被任何线程获取。3、问题3：绝境求生从问题2的分析过程可以看出log_sys->log_flush_order_mutex没有被任何线程获取到，但是为什么446线程没有被唤醒呢？是信号丢失还是程序问题？信号丢失，为什么能稳定恢复？现在？官方bug列表中没有类似的bug。我搜索了社区，发现可用的信息非常少。这时候分析好像陷入了死胡同，心里的压力无形中开始增加……好像没有办法，但是任何问题都是有原因的，如果找到原因，有解决办法……又一次把注意力转移到Thread446的栈上，然后查看函数：从问题2的分析过程可以得出一个线程在log_flush_order_mutex_exit退出过程做了没有唤醒Thread446，所以跟着这个函数看它是如何唤醒其他进程的。实在没办法的时候，也就只有这么一步步分析代码了。我希望有所收获。随着函数调用的不断深入，将目光投向了mutex_exit_func，函数中的注释引起了我的注意：从上面的注释中可以得到两点信息：由于内存屏障的存在，mutex_get_waiters&mutex_reset_lock_word的调用顺序可能与执行顺序相反。在某些情况下，它会导致挂起问题；专门写了一个函数sync_arr_wake_threads_if_sema_free()来解决上述问题。从上面的注释可以看出，并不是信号丢失了，而是多线程内存屏障的存在可能导致指令执行顺序不正常。这种问题肯定存在，但是既然有sync_arr_wake_threads_if_sema_free()来避免这个问题，为什么还会存在呢？挂机呢？有了这个线索，我觉得有些希望了。。。经过查找，sync_arr_wake_threads_if_sema_free只在srv_error_monitor_thread中被调用。该线程是监控MySQL内部异常情况并打印错误信息的线程。臭名昭著的600S自杀案也是它的杰作，那么问题来了：周末机器挂了，为什么没有检测到异常而中止呢？既然sync_arr_wake_threads_if_sema_free可以唤醒，那为什么没有唤醒呢？顺着这个思路，查看pstack中srv_error_monitor_thread的栈，可以发现这个线程在获取log_sys->mutex的时候挂了，所以无法执行sync_arr_wake_threads_if_sema_free()&正常返回异常检查，正好回答了上面的问题。详细堆栈如下：经过上面的分析，问题越来越清晰了，流程可以简单概括为：线程446获得了log_sys->mutex，但是在等待log_sys->log_flush_order_mutex的过程中没有被唤醒；ThreadXXX在释放log_sys->log_flush_order_mutex的过程中出现内存屏障问题，没有唤醒Thread446；线程470在获取log_sys->mutex时挂掉，导致无法执行sync_arr_wake_threads_if_sema_free()，导致整个实例挂掉；Thread470需要获取Thread446的log_sys->mutex，Thread446需要Thread470唤醒释放log_sys->mutex；结合log_sys->log_flush_order_mutex的状态信息，instancehang的全过程如下：关于Memorybarrier的介绍可以参考：https://en.wikipedia.org/wiki/Memory_barrierhttp://name5566。com/4535.html问题解决既然知道了问题的原因，那么问题就可以顺利解决了。有两种方法：这里直接去掉log_get_lsn的判断，它本身就是开发者添加的一些判断信息，写的用来定位LSN的异常，用的时候就崩溃了，用处不大；保留判断，将log_get_lsn改为log_peek_lsn，后者会先执行try_lock，发现锁失败直接返回，不做判断，这种方式比较优雅；修改后的版本在测试过程中没有重现这个问题。虽然问题已经解决了，但是正式版肯定存在这个问题。为什么找不到错误列表？查阅了相关资料，查看了***代码，发现已经修复了这个问题。修复方法就是上面列举的第二种方法。详细的commitmessage信息如下：bug影响范围：MySQL5.6.28及之前版本均存在该问题。
