MySQL源码：Innodb两次写与多实例buffer pool的一个BUG的说明与解决
2012-12-05 14:06 竹 石 阅读(2266) 评论(14) 编辑 收藏 举报之前发了一条微博称，那天是个好日子，一直困扰我的两个问题那天一次性解决了，一个是由于我理解不够深，不是问题被误认为是问题，最后由老大指点解决（在http://www.cnblogs.com/bamboos/archive/2012/05/15/2502259.html中的一个评论有说明）；后面一个问题还真是问题，是由于INNODB的一个BUG导致，找了好几天才终于找到原因，现在就叙述一下这个问题的问题。
问题的经过是这样的，我实现了一个MYSQL多线程复制的patch，是按照表名来划分的，相同的表会分到同一个线程中做，实现的是BINLOG_FORMAT为STATEMENT的，那么这样就实现了并发。
在我测试过程中，使用的是自动提交，一条语句为一个事务，开8个线程的话大概是单线程复制的5倍（共有20个表），性能应该还是不错的，多线程下QPS可以达到32000，单线程差不多6500，但是这是把double write关了的情况，如果打开了double write，那么一开始的QPS也差不多是32000，但做几分钟之后，这个数字一直在减小，那个感觉啊真是不好，怎么老是一直减少呢，等到跟上来了，一直看着它减少到15000，这个很不好，相当于是2倍的提升，这个看上去完全是因为double write的影响，因为只是修改了这么一个参数而出现的两个不同的结果，但是查遍了网上也都说double write的影响只会是5-10%，那么就奇怪了，我这个的影响明显是50%以上啊，难道是两次写就是50%？不对的，因为double write本来就是连续写的。肯定是哪里有其它的问题。
然后在无奈之下，在测试时，通过pstack工具看MYSQL运行时慢到底是什么样的堆栈，到底是在等啥？什么影响了它的性能，然后看到很多时候堆栈都是这样的：
Thread 4 (Thread 0x7fdadd357700 (LWP 9800)):
#1 0x00000000008d3007 in os_event_wait_low ()
#2 0x00000000008230ae in sync_array_wait_event ()
#3 0x0000000000823f46 in mutex_spin_wait ()
#4 0x00000000008674df in buf_flush_buffered_writes ()
#5 0x0000000000868b97 in buf_flush_batch ()
#6 0x000000000086a6df in buf_flush_list ()
#7 0x00000000008c31b2 in log_check_margins ()
#8 0x00000000008eba6a in row_ins_index_entry_low ()
#9 0x00000000008efd9e in row_ins_step ()
#10 0x0000000000803be9 in row_insert_for_mysql ()
#11 0x00000000007f2d6c in ha_innobase::write_row(unsigned char*) ()
#12 0x000000000068c760 in handler::ha_write_row(unsigned char*) ()
#13 0x000000000055a2ed in write_record(THD*, TABLE*, st_copy_info*) ()
Thread 3 (Thread 0x7fdadd316700 (LWP 9801)):
#1 0x00000000008d3007 in os_event_wait_low ()
#2 0x00000000008230ae in sync_array_wait_event ()
#3 0x0000000000823f46 in mutex_spin_wait ()
#4 0x00000000008674df in buf_flush_buffered_writes ()
#5 0x0000000000868b97 in buf_flush_batch ()
#6 0x000000000086a6df in buf_flush_list ()
#7 0x00000000008c31b2 in log_check_margins ()
#8 0x00000000008eba6a in row_ins_index_entry_low ()
#9 0x00000000008efd9e in row_ins_step ()
#10 0x0000000000803be9 in row_insert_for_mysql ()
#11 0x00000000007f2d6c in ha_innobase::write_row(unsigned char*) ()
#12 0x000000000068c760 in handler::ha_write_row(unsigned char*) ()
#13 0x000000000055a2ed in write_record(THD*, TABLE*, st_copy_info*) ()
从上面的堆栈中可以看出，SQL线程很多都是在buf_flush_buffered_writes函数中等待，而这个函数正好是处理double write的函数，所以我重点看了这里，然后一进去就明白了是为什么了，看到这个函数一开始有一行mutex_enter(&(trx_doublewrite->mutex))，而在函数退出前有一行mutex_exit(&(trx_doublewrite->mutex))，里面是处理所有double write缓存起来的页面，也就是前面要刷的页面，因为INNODB支持多个BUFFER POOL实例，这样可以增大并发度，页面可以放在不同的BUFFER POOL中，这样两个BUFFER POOL中的页面在同时访问时可以互不干扰，那么可想而知，double write缓存的页面就是来自多个SQL线程并发收集起来的，那么很容易想到，问题其实就里在这里，由多个线程做检查点，但只有一个线程会做double write，这样产生了瓶颈，导致等待一段时间后就会越来越慢，也许就是这个问题，那后面就看了一下代码，它的实现是否允许多个线程做检查点呢，主要是看函数log_free_check（log_check_margins）的实现，因为这个函数才是用户线程调用的，代码是这样的：
log_free_check(void)
{
if (log_sys->check_flush_or_checkpoint)
log_check_margins();
}
那就主要是log_sys->check_flush_or_checkpoint有没有可能多个线程进来了，最后发现在里面直接就调log_checkpoint_margin函数了，而再进去里面，就是对buffer pool中的脏页面进行刷盘了，同时这里刷盘是刷每一个buffer pool instance的，而不是分开自己刷自己的，当然对于某一个buffer pool instance，只会有一个线程做，进来之后会找到没有任何一个线程在做刷盘的buffer pool instance来做，所以其实是并发处理这多个buffer pool instance的，那么现在得到的结论就是经常性的多个线程一起做刷盘操作，而做完刷盘之后，如果打开了double write，则要将所有的buffer pool instance要刷的页面做double write，上面也看到了，它是一个mutex，多个线程一起抢这一个临界区，导致系统的并发度大大的降低，那么现在问题已经很明显，原因也已经很明显，这个其实与DOUBLEWRITE没关系，那个5-10%我还是承认的，这里只不过是代码实现有问题而已。
那么结论就里说，这其实是INNODB的一个BUG，就是多BUFFERPOOL实例下，DOUBLEWRITE会导致系统并发性能大大降低的问题。
那如何解决呢？
首先我已经向bugs.mysql.com报了BUG，链接http://bugs.mysql.com/bug.php?id=67808&edit=2，本人英语不好，写得挺费劲。
难道就这样等它解决吗？不对，我已经等不上了，即使出来了也不是在5.5.27上啊，所以自己解决吧。
这里归根结底的问题就是做检查点函数log_checkpoint_margin中存在并发，导致DOUBLEWRITE的瓶颈出现了，因为在INNODB的增删改操作的一开始，都会直接先调用log_free_check这个函数，出现这样的问题的概率太高了。
想想，这个做检查点需要多个线程吗？如果是一个线程在做是不是就没有问题了？DOUBLEWRITE的瓶颈也不存在了？确实是这样的。
再想想，做检查点需要多个线程吗？只有一个线程做是不是就够了？因为检查点归根结底是为了给日志让空间出来，日志一直往2个（默认）日志文件中循环添加，第一个写完写第二个，写完第二个再写第一个，其实就里一个圈，不断的循环，那么这里就必须要保证，向里面写的数据的位置不能走到检查点的位置的前面去（因为数据的LSN是新产生的日志的LSN，肯定是要小于检查点的LSN的，也可以表示为，数据的LSN必须要小于检查点的LSN加上整个日志组的日志容量），因为检查点LSN前面的日志表明，所有数据已经都写入磁盘了，可以扔掉了，那如果大于了，就会把没有做检查点的日志覆盖掉，这样会导致数据错误或者更严重的一些问题。
有了这样的想法，则这个问题应该不难解决，先在log_sys中加入一个成员checkpoint_doing，用来表示现在是否有线程正在做检查点，再修改函数log_check_margins，最前面加上代码段：
mutex_enter(&(log_sys->mutex));
if (log_sys->checkpoint_doing > 0) {
mutex_exit(&(log_sys->mutex));
return;
}
log_sys->checkpoint_doing++;
mutex_exit(&(log_sys->mutex));
上面这表示如果有线程已经做了，那这里不会再进去，直接就出去了，如果没有线程在做，那么当前线程才做，同时将标志置为正在做。这样保证了只有一个用户线程会做检查点。当然在修改及判断这个checkpoint_doing的时候必须要对其进行保护，上面代码中也已经有所体现。
那么这样就好了吗？如果当前系统的压力非常大，那么出去了，而没有做检查点检查，继续做写操作，这样有可能会导致新的日志写的超过了检查点的位置，导致数据覆盖，所以还需要做一个修改操作。
因为在INNODB中写日志的函数只有log_write_up_to，并且这只会有一个线程写，那么为了防止这个问题的话是不是在它写日志的时候检查一下，如果空间不够了等待或者做一次检查点后再继续做，是不是就没有问题了？我认为确实是这样的，那么继续修改：
if (!log_sys->checkpoint_waiting && log_sys->lsn - log_sys->last_checkpoint_lsn > log_sys->max_checkpoint_age)
{
mutex_exit(&(log_sys->mutex));
log_sys->checkpoint_waiting = 1;
log_check_margins();
log_sys->checkpoint_waiting = 0;
goto loop;
}
这段代码就加在log_write_up_to函数中五个判断条件之后，能走到这里说明这次的日志要写入日志文件了，那么这里检查是最合适的，上面的代码有一个条件判断，最主要是的log_sys->lsn - log_sys->last_checkpoint_lsn > log_sys->max_checkpoint_age，这个表示的是如果当前的最新LSN超过检查点LSN的数目已经大于最大的做检查点差值数，则就等待或者做一次检查点，这个条件与log_checkpoint_margin函数中判断是不是要做检查点的条件是一样的，这样的话就保证了这段代码中调用了log_check_margins时要么里面已经有人正在做，要么自己肯定能做一次检查点，不然在这里会产生死循环。做了之后从而使的log_sys->last_checkpoint_lsn变大，向前走，让出空间，这样这次日志就可以写入进去了，那么goto loop可以起到循环等待的作用。
上面还看到一个新的成员checkpoint_waiting，这个是为了防止进入死循环而设置的，因为log_check_margins里面还会再调用log_write_up_to。
那么到现在为止，这个问题应该算是可以了的，接下来就是测试了，把多线程的SLAVE复制跑起来，我发现这个是一个非常好的并发测试工具，不需要专门写应用来设置并发环境。
测试的结果表明，那么问题不复存在，平均的QPS在打开DOUBLEWRITE时都是31000，这个数字挺好的。问题解决，同时发现那个分支就从来没有进去过，说明用户线程做了已经足够了，那里只是一个机率很小的问题预防而已。
但是这个修改现在还没有办法去验证，只能由各位先从理论上看看是不是正确吧，我本人认为应该还是没什么大问题的，请各位大侠指点！
这里要感谢一下我的好朋友好战友陈福荣同学，在MYSQL学习及实现方面一直不断的讨论，研究，我们共同进步。
