作者介绍去哪儿网数据库负责人王柱峰。擅长数据库开发、数据库管理和维护，一直致力于MySQL数据库源码的研究和探索，对数据库原理和实现有深刻理解。曾就职于大梦数据库，从事数据库内核开发多年。是Inception开源项目和《MySQL运维内参》的作者，MySQL方向的OracleACE。一、背景群里的同学最近遇到了一个问题，说是数据库被业务杀了没有反应，只好用kill-9pid杀掉，然后重启。好在此时数据库的角色是从库，影响不大。同学说，kill掉重启的时候心想，千万不要启动失败，这个库的数据量有点大，马上就要到4T了。做运维的都知道，事情不应该说出来的，一说出来，这个事情就会发生。这次也不例外，它确实出现了。现象是长时间无法启动，基本卡死。错误日志信息如下：通过查看note级启动日志，发现报完最后一条后，没有新的日志出现。久久不动。二、分析1、TOP命令首先使用top命令判断当前实例是否还处于活动状态：PID为84448，发现CPU占用为0，说明当前实例卡死，没有运行。当然不是死循环（因为是死循环，CPU肯定是满载的）。2.栈下一步就是看栈了。这是检查问题时非常好的工具。堆栈结果如下：从堆栈可以看出IO线程根本没有工作，处于空闲状态。启动线程，也就是包含mysqld_main函数的栈，也处于nanosleep状态。已经解释了两组主要的线程。当前实例是什么？也不做，完全闲着，这和我们上面用TOP判断的结果是一样的。3、进一步分析从上面的现象来看，很难找到具体的原因，因为很难判断当前线程为什么这么死等，当然从启动线程基本可以判断是启动时的一个checkpoint，但是刷盘的时候等不到刷完，基本上只能这样了。那么我们可以想象一下，等待刷盘，但不等待，刷盘线程在干什么？这也很容易确认。了解源码的同学应该明白，刷盘线程是buf_flush_page_cleaner_coordinator，如上图堆栈截图所示。我们再来看看。显然这个线程也处于等待状态，所以可以大致推断InnoDB内部应该有问题。磁盘刷新线程认为没有什么可刷新的，所以处于空闲状态，而启动线程认为有什么可刷新的，所以一直在等待，信息没有对齐，所以等死了。能否继续单纯从以上信息来分析呢？也许它可以改进一点。我们发现在上面的错误日志中，有这样一行信息：2021-08-27T16:50:24.433063+08:000[Note]InnoDB:Completingtruncatefortablewithid(93752)residedinginfile-per-tableid为（12742）的信息表空间比较少见。大概意思是某个表在重启前被truncate过，重启的时候，这个表需要redotruncate一次。而我们逆向查看启动栈，发现调用buf_flush_wait_flushed的恰好是truncate_t::fixup_tables_in_non_system_tablespace，发现这也是truncate，好像是匹配的，所以这个时候我们可以猜测是不是有什么关系与截断。咨询业务后，发现在这个实例的生命周期内，确实多次加载和截断数据，才知道这个业务的行为。有用吗？试想从上面的现象，我们是不是可以进一步分析一下呢？在这一点上，我认为这是不可能的。那么该怎么办？我认为这只是源代码。4.源码分析我们使用源码分析。首先要解决的是为什么信息不对称，即刷入线程认为没有页面刷入，启动线程却认为需要刷入？使用源码分析，一个很重要的出发点就是先编译一个同版本的Debugmysqld，然后开始重现这个问题，因为这个问题是一定会出现的，这样查找起来就容易多了。重现之后，我们再看看上面的堆栈：有没有发现很大的不同？还有很多信息。可以详细看到每个函数对应的文件、行号等。上面显示了刷盘线程buf_flush_page_cleaner_coordinator的状态，代码版本是Percona5.7.26，可以看出os_event的等待位置在buf0flu.cc的3212行，我们得到对应的代码，看看是什么这条线是干什么的。可以看到，3212行的代码是os_event_wait(buf_flush_event)。这条线上方是闪烁线程的起始位置。熟悉代码的同学都知道，这个位置是用来把innodb恢复过程中REDOreplay产生的脏页刷到文件中的，在这一行之后，也就是我们可以看到下面的那行代码开始while(srv_shutdown_state==SRV_SHUTDOWN_NONE){，真的是把我们数据库正常运行时产生的所有脏页都刷掉了。操作产生的脏页被分阶段刷新。知道了这个我们就可以知道3212行是两个阶段的分界线，也就是说flashing线程认为数据库的REDO已经完成，但是还没有启动完成，所以正常闪烁还不能开始做，所以就在这里静静等待。我们回头看看此时启动线程的位置。堆栈如下：熟悉代码的同学都知道innobase_start_or_create_for_mysql是innodb启动的关键函数。这里我们调用了truncate_t::fixup_tables_in_non_system_tablespace，从名字可以推断出它是做什么用的？它与日志中的最后一行非常相关。我们可以看一下日志打印在哪里。代码如下：一目了然，就是由于日志文件打印了这一行，所以启动卡在了这里。很清楚，代码验证了我们的推测。我们现在需要考虑的问题是，为什么innodb会觉得这个位置需要刷新呢？我们再看一下代码：这里是函数truncate_t::fixup_tables_in_non_system_tablespace的最后一个位置，这里我们可以看到函数log_make_checkpoint_at的调用，我们可以在栈中看到，其实他卡在里面了。这里也是同样的问题，为什么要刷盘呢？因为在这个fixup过程中，做了很多修改操作。修改内容可以参考上图中函数row_truncate_update_sys_tables_during_fix_up的实现。里面做了很多修改，SQL语句的执行肯定会产生很多脏页。所以innodb需要flush它。但是为什么闪烁的线程不再闪烁了？显然，正如上面解释的那样，他已经执行完了redoreplay产生的脏页，所以他已经处于idle状态。他认为他不会在数据库启动前再次刷盘，除非设置一次buf_flush_event事件。那么我们的好奇心来了，buf_flush_event一般是什么时候设置的呢？再看代码，一共有两个地方，先看第一个：从上图可以看出，设置在srv0start.cc的2892行，如果执行到这一行，那么闪烁线程会继续执行完，就说明innodb启动后可以正常工作了，现在看看truncate_t::fixup_tables_in_non_system_tablespace()是什么时候调用的？从栈中可以看出是srv0start.cc:2644行的位置，也就是设置buf_flush_event之前的位置，也就是说innodb认为fixup执行产生的脏页还是REDOreplay产生的（随便这么想吧），那么问题来了，在这种情况下，为什么闪烁线程会提前退出呢？我们再看代码，对于REDOreplay产生的刷脏页工作，刷盘线程在什么情况下会退出：可以看到其中一个循环退出条件是recv_sys->heap==NULL，也就是说，只要recv_sys->heap==NULL，刷机操作就会退出。再看看recv_sys→heap设置为NULL的时候：不难发现recv_sys_debug_free中recv_sys→heap设置为NULL了，现在问题就变成了recv_recovery_from_checkpoint_finish是什么时候调用的。熟悉代码的同学应该很清楚这一点。这是完成REDO重放的重要功能。我们查找发现：可以看到recv_recovery_from_checkpoint_finish的调用位置，在2618行，是在调用fixup_tables_in_non_system_tablespace之前。细心的同学可能还会从上图中发现有一个类似的函数truncate_t::fixup_tables_in_system_tablespace()。看名字就知道，这是针对系统表的。总之，无论系统表还是NON系统表，都是在recv_recovery_from_checkpoint_finish之后调用的，因为之前分析过只要调用recv_recovery_from_checkpoint_finish，磁盘清理线程就认为innodb产生的脏页是正常的脏页，并且不会在负责刷盘后，会去等待buf_flush_event的位置，但是启动线程并不这么认为。重放完成后，会产生新的脏页。同时他认为这里产生的脏页一定要flush掉。此时buf_flush_event还没有设置，所以启动线程只能等待。是的，会一直等下去。我们现在来看设置buf_flush_event的第二个位置，也就是buf_flush_request_force，这个函数调用的位置我们已经很熟悉了。请看：同时我们发现buf_flush_request_force下面是我们目前陷入死循环的函数。也就是说，InnoDB也认为fixup产生的脏页应该在启动后由flushingthread进行flush，也就是只有在事件buf_flush_event存在后才进行flushdisk。所以上面在进入等待状态buf_flush_wait_flushed之前，先对buf_flush_event进行一次Set操作，让刷新线程继续往下执行，进入正常刷新状态。但是，当前启动线程已经处于等待状态，为什么刷新线程还在等待事件buf_flush_event呢？细心的同学应该注意到了，在上图中，buf_flush_request_force的调用是有条件的，还有一个参数srv_flush_sync。这时候我看了一下当前参数的值，是0，可以解释，正是因为这个参数导致这个机制失效。这里buf_flush_event的Set是无效的。需要依赖上面第一种情况中提到的Set。这个时候，你已经明白，你永远不会在那里执行，会永远等待。.现在应该清楚了，对于这个问题，整个流程是没有问题的，但是有一个参数srv_flush_sync，导致了逻辑上的漏洞。我们怎样才能避免这样的问题呢？显然，可以通过参数控制来避免。问题是最友好的，我们只需要将参数srv_flush_sync（实际上是InnoDB的参数innodb_flush_sync）设置为ON即可。清楚buf_flush_wait_flushed函数的状态后，我们再回头看看buf_flush_wait_flushed函数死掉的位置状态是什么样的，如下图所示：从图中可以看出有很多脏页，并且theoldestislessthan任意buffer实例中最新的lsn，有兴趣的同学可以查看源码。循环退出的条件是oldest大于eachinstance_newest，oldset始终不变，始终为103036344355008，小于each，为什么oldest不能变大呢？是因为buf_flush_page_cleaner_coordinator线程没有正常工作。而这里我也需要纠正一下我上面的一个判断，就是我在TOP看到CPU很空闲，占用率为0，所以我认为不是死循环。这是不准确的，因为我们会发现buf_flush_wait_flushed函数中的等待也是一个死循环，但是有一行代码：注释有说，sleep然后重试，buf_flush_wait_flushed_sleep_time是什么？从代码中可以看出硬编码为10000微秒。很明显，以这样的频率进行无限循环不会使CPU忙碌。5.解决方案既然问题明确了，那么如何解决呢？数据不会改变。截断是在实例还活着之前完成的。这是无法更改的。最简单的方法之一是重做数据。这个确实很简单，但是想想，4T的数据，时间成本太高了，DBA做这样的事情已经很烦了。1.解决方案——有没有更简单快捷的方法？确实如此，因为我们编译的是debug版本，而且我们在上面看到buf_flush_wait_flushed函数已经是死循环了，我们也知道因为传入的LSN_MAX值不能满足循环结束条件通过new_oldest这个参数，所以就死循环了，那如果我们能让这个循环早点结束，条件满足，不就可以了吗？这样的功能用GDB就可以实现，直接实战图：看到这个，感觉就像在开特斯拉。一旦踩下“油门”，邓就会被开除。数据库会瞬间快速正常运行，死循环会突然断掉，马上启动。2、解决方案2还有一个解决方案，就是重启一次，而不是依赖当前的启动进程。重启前把参数innodb_flush_sync改成ON，这样启动就没有问题了，成功避免了此类问题。.3.解决方案3具体到这个问题，如果可以确认是truncate本身在运行，而不是其他内部原因，可以删除data目录下对应的*_trunc.log文件，这样数据库加载的时候就不会加载了starts如果有相关资料，就没有问题。当然，这种方法要慎用，因为毕竟是在破坏物理数据，加上上面那种可以使用参数控制来避免问题的方法，其他解决问题的方法就可以不屑一顾了。因为我选择了gdb方法来解决这个问题，其他两种方法我都没有机会实践，唉！！！6.补充问题：按照上面的启动方式，可以正常启动数据库，但是如果关机，下次重启，还会出现这个问题吗？答案是否定的，因为正常启动后，truncate相关的日志已经清空，所以重启时不会再调用truncate_t::fixup_tables_in_non_system_tablespace函数，所以不会有问题。7.问题澄清我打算向bugs.mysql.com报告一个错误。为了更准确的展示问题，找了MySQL官方代码版，找到函数log_preflush_pool_modified_pa??ges。发现和我们上面分析的代码不太一样，如下图所示：可以看出正式版代码没有这个问题，因为出错的时候new_oldest是LSN_MAX，在这个case，会进入图中有横线的分支，这里不存在死等待问题，只有指定了特定的LSN值进行闪现，才会去到后面的分支。可以大胆猜测，这个问题应该是Percona新解决的问题，至今没有发现。8.问题总结现在我们清楚了，很明显这是一个bug，通过我们的分析，我们可以通过在buf_flush_event后面加上fixup来修复这个bug，应该不会出现这个问题，但是这个还是需要通过官方修改，作为运维人员，我们只需要在遇到问题的时候学会如何规避即可（当然要报bug），当然如果我们想尝试修复这个问题也是可以的，但又要保养，不容易。如果没有相应的人力和团队，最好不要走这条路。如果事情不顺利怎么办？这种损失可能更大。这个问题可能遇到的人比较少，所以看了最新版的Percona5.7.33，代码没有变化，也就是说目前没有修改。也说明官方没有测试truncatefull的问题。另外，我们需要思考一个问题。对于这个bug，如果我们对源码了解不多，是不是可以解决这个问题呢？你知道为什么吗？我觉得未必可以，也应该是不可能的。这也从侧面说明了掌握源码对于一个DBA来说是多么的重要。这是一个使用源码解决问题的真实案例，这个问题怎么会和参数innodb_flush_sync有关呢？MySQL手册没有告诉您这一点。DBA这个职业一直被很多业内人士认为是被机器取代的。确实，因为云时代的出现，自动化平台的出现，很多操作都被机器代替了，所以结论是DBA已经不重要了，很快就会被淘汰。在我看来，这个结论显然是错误的。云时代和自动化平台的出现，只能让DBA的入门门槛更高，让DBA的工作效率更高，让DBA承担更重要的任务。有时间去解决更复杂的问题，才有精力去搭建更好的平台和架构，做更有价值的输出。而学习源码是成为不被淘汰的DBA的最佳捷径。更重要的是，您的职业是MySQLDBA。MySQL给你一个学习源码的机会，让你学习源码，这是其他数据库无法替代的。
