记MySQL的一次启动异常

1.背景

测试环境一直运行良好的MySQL突然莫名挂掉，登上机器重新启动，居然没启动起来

2.寻找原因

尝试一: 查找问题最简单的方法当然是先看日志报错:

如图1所示MySQL启动异常系命中了红框内的断言错误所致，根据那行代码大概猜测可能是buf的长度不够导致的异常。这时候接着往下看，发现MySql提示要保证系统内存满足如下大小:

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 68255 K

故查看系统所剩内存发现还有10G可用空间，远远超过MySQL所需的65M大小

尝试二:到这里错误日志已基本分析完毕，已没有什么可供继续排查的线索了，此时只有祭出源码调试大法了

(1)启动gdb调试MySQL

gdb -q /usr/local/mysql/bin/mysqld

(2)根据图1的报错位置设置断点并启动程序

(gdb) b log0log.cc:1105
Breakpoint 1 at 0x19ab4bd: file /data/home/jessemiao/install/mysql-5.7.19/storage/innobase/log/log0log.cc, line 1105.
(gdb) r
Starting program: /usr/local/mysql/bin/mysqld

(3)打印当前堆栈，瞬间发现造成断言错误的元凶

堆栈信息中最上层函数参数pad_len=0、len=1024，结合断言错误assertion可知pad_len值异常导致了程序异常。此时我们需要寻找元凶pad_len的来处
(4)寻找元凶pad_len的来处，根据堆栈信息很容易找到log_write_up_to函数
该函数涉及到排查问题的关键代码如下:

如图3所示粉色框住的函数则为发生断言错误所在的函数，其上方红色框住的即为断言错误的元凶。可以发现pad_size初始定义为0，只有俩处地方需要修改其值，而要修改其值则要满足条件判断:

end_offset_in_unit > 0 && (area_end - area_start) > end_offset_in_unit

根据打印各个变量的值发现是图3绿色框部分的end_offset_in_unit变量为0导致修改pad_size的条件不成立。而end_offset_in_unit值则为:

end_offset_in_unit = (ulint) (end_offset % write_ahead_size); 

根据gdb打印变量套用上述表达式：end_offset_in_unit = 16777216 % 8192 = 0
end_offset_in_unit(根据end_offset、end_offset_in_unit表达式变量名猜测end_offset_in_unit为在某块写block上的偏移位置)值为0很正常(1/8192的概率)，但是它为0了就会使断言错误的直接凶手pad_size不能得到有效值进而引发MySQL启动异常。

3.解决问题

既然知道了是某个变量在任意block偏移位置为0导致的MySQL启动异常(概率为1/8192)，难道这么大的bug刚好被我遇到了？那么问题如何解决？

这时候突然发现图3中pad_size变量传参时居然是条件编译:

根据图四可猜测出pad_size只有在debug模式下才会传参给断言错误所在的函数。那么将当前MySQL bin替换成非debug模式的bin是否就能解决问题？

于是根据当前MySQL版本源码进行重新编译，在cmake时不加-DCMAKE_BUILD_TYPE=Debug选项，使用编译出的bin再次启动MySQL，果然启动成功了。

问题得到解决，猜测问题原因可能是MySQL debug模式下的一个不严谨的小bug(1/8192概率出现)

4.总结

在遇到开源组件异常时，如果根据日志无法找到解决异常的蛛丝马迹时，不妨大胆的去调试源码。源码才是凶案的第一现场，即使我们看不懂大部分内容，但只要抓住源码里涉及异常的核心点，相信总归会得到一些有价值的帮助。