之前发了一条微博称,那天是个好日子,一直困扰我的两个问题那天一次性解决了,一个是由于我理解不够深,不是问题被误认为是问题,最后由老大指点解决(在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学习及实现方面一直不断的讨论,研究,我们共同进步。