环境及测试现象

在同一个硬件环境下，相同的mysql数据库环境(日志写模式都设置为双0，0)，使用相同的测试工具 sysbench和相同的测试参数，进行两次混合读写(3:1)的测试，我们分别定义为测试一和测试二。

测试一的TPS如下图所示，相对平稳。

1.png
我们再来看测试二的TPS如下图：
2.png
很明显有如下现象
a、测试二的波动幅度还是相当大的，而且相当的有规律。
b、测试二的性能结果是要比测试一高很多的,峰值基本稳定在58K tps,而测试一就50K左右。
以上信息，我们初步能排除的因素有以下几点：
1.硬件问题可排除（通过两次测试，只要有一次OK，即可排除硬件问题）
2.工具问题可排除（相同参数测试两次，只要有一次OK，即可排除工具问题）
3.测试工具的参数问题，同理可排除。

  1. 测试过程数据

    在1,1000模式下，每秒日志写40~60MB，数据写118MB,性能TPS 39K

  2. 进一步分析一

    先将测试一进行重复测试，发现能稳定复现测试二的抖动现象。
    那么第一次测试一应该有问题。下面可以聚焦测试过程中的性能抖动本身，而非测试一和测试二之间的差异。

  3. 进一步分析二

    修改数据库数据的写入策略。
    将innodb_flush_log_at_trx_commit和sync_binlog 两个参数，设置为双1或者1，1000，并没有出现抖动情况。而设置为双0会出现抖动情况（测试二就是双0情况），从这一步可以推测是测试一中该参数可能设置未生效。
    抖动情况平均在10秒左右出现一次非常规律。日志缓存最慢是1秒刷一次可以排除日子缓存刷一次引发的IO问题，但是数据缓存和bincache就不确定了这个需要进一步分析。查看测试系统我们参数如下，max_binlog_cache_size为2G,max_binlog_size为500M，binlog_cache_size为32K。
    max_binlog_cache_size | 2147483648
    max_binlog_size | 524288000
    binlog_cache_size | 32768
    我们发现max_binlog_size刚好换算一下是500MB，而按照每秒50MB写日志的速度就刚好是10秒左右，是不是很巧合？那么问题就变成了sync_binlog在0模式下，是写满max_binlog_size后才会刷的磁盘么？我们知道在sync_binlog在1模式下，binlog是提交一次事务就刷，在1000模式下，是写满1000次就刷。
    从理论来看是具备这个可能性的，因为在0模式下，binlog_cache是不主动去刷了要等操作系统来处理，而现在测试系统中定义的文件大小就是500M，当在内存中写满500M缓存中的时候如果再不刷就溢出了，到了一个不得不刷的时间点。
    但是理论推断还需要实际数据证明。

  4. 进一步分析三

    放大max_binlog_size 从500M变成1000M，抖动频率从10秒左右增加到18~20秒左右，验证了我们再分析二中的猜测。
    监控数据库每秒刷日志在50MB左右，这个是刷到CACHE的，等累计到1000MB后会刷到磁盘中mysql-bin.0000X文件中（累积需要的时间就是20秒左右），此时就会导致性能下跌。而在数据库参数sync_binlog参数在1或1000下不会存在等到写满才刷磁盘的现象，也就不存在性能抖动问题了。如下数据显示，斜体为两次出现抖动的情况，中间为所经历的时间。从IOSTAT监控IO也发现 在抖动那一秒日志所在磁盘的IO会暴增一下，其他时间点是没有写操作的。
    [ 571s] threads: 128, tps: 37666.00, reads: 0.00, writes: 113177.00, response time: 2.78ms (95%), errors: 0.00, reconnects: 0.00
    [ 572s] threads: 128, tps: 0.00, reads: 0.00, writes: 0.00, response time: 0.00ms (95%), errors: 0.00, reconnects: 0.00
    [ 573s] threads: 128, tps: 39471.34, reads: 0.00, writes: 118196.02, response time: 2.87ms (95%), errors: 0.00, reconnects: 0.00
    [ 574s] threads: 128, tps: 56711.07, reads: 0.00, writes: 170113.21, response time: 2.75ms (95%), errors: 0.00, reconnects: 0.00
    [ 575s] threads: 128, tps: 56042.01, reads: 0.00, writes: 168147.03, response time: 2.79ms (95%), errors: 0.00, reconnects: 0.00
    [ 576s] threads: 128, tps: 56507.81, reads: 0.00, writes: 169496.42, response time: 2.76ms (95%), errors: 0.00, reconnects: 0.00
    [ 577s] threads: 128, tps: 56474.98, reads: 0.00, writes: 169463.94, response time: 2.74ms (95%), errors: 0.00, reconnects: 0.00
    [ 578s] threads: 128, tps: 56200.02, reads: 0.00, writes: 168617.06, response time: 2.75ms (95%), errors: 0.00, reconnects: 0.00
    [ 579s] threads: 128, tps: 56548.16, reads: 0.00, writes: 169600.49, response time: 2.75ms (95%), errors: 0.00, reconnects: 0.00
    [ 580s] threads: 128, tps: 56428.96, reads: 0.00, writes: 169323.89, response time: 2.73ms (95%), errors: 0.00, reconnects: 0.00
    [ 581s] threads: 128, tps: 56080.99, reads: 0.00, writes: 168202.97, response time: 2.75ms (95%), errors: 0.00, reconnects: 0.00
    [ 582s] threads: 128, tps: 55537.04, reads: 0.00, writes: 166614.13, response time: 2.82ms (95%), errors: 0.00, reconnects: 0.00
    [ 583s] threads: 128, tps: 56016.05, reads: 0.00, writes: 168074.16, response time: 2.79ms (95%), errors: 0.00, reconnects: 0.00
    [ 584s] threads: 128, tps: 56461.91, reads: 0.00, writes: 169369.73, response time: 2.76ms (95%), errors: 0.00, reconnects: 0.00
    [ 585s] threads: 128, tps: 56139.98, reads: 0.00, writes: 168483.94, response time: 2.77ms (95%), errors: 0.00, reconnects: 0.00
    [ 586s] threads: 128, tps: 56058.06, reads: 0.00, writes: 168152.17, response time: 2.80ms (95%), errors: 0.00, reconnects: 0.00
    [ 587s] threads: 128, tps: 55952.98, reads: 0.00, writes: 167842.95, response time: 2.81ms (95%), errors: 0.00, reconnects: 0.00
    [ 588s] threads: 128, tps: 55815.97, reads: 0.00, writes: 167419.91, response time: 2.81ms (95%), errors: 0.00, reconnects: 0.00
    [ 589s] threads: 128, tps: 56340.02, reads: 0.00, writes: 169001.05, response time: 2.78ms (95%), errors: 0.00, reconnects: 0.00
    [ 590s] threads: 128, tps: 1092.00, reads: 0.00, writes: 3519.00, response time: 2.63ms (95%), errors: 0.00, reconnects: 0.00
    [ 591s] threads: 128, tps: 16467.01, reads: 0.00, writes: 49154.02, response time: 2.87ms (95%), errors: 0.00, reconnects: 0.00
    继续验证，将max_binlog_size增加到250M，那么抖动时间会变成5秒左右，如果现象和预计的一样那么问题解决。
    Bingo，现象如下：
    [ 209s] threads: 128, tps: 55708.17, reads: 0.00, writes: 167155.50, response time: 2.84ms (95%), errors: 0.00, reconnects: 0.00
    [ 210s] threads: 128, tps: 31682.01, reads: 0.00, writes: 95064.02, response time: 2.88ms (95%), errors: 0.00, reconnects: 0.00
    [ 211s] threads: 128, tps: 55643.02, reads: 0.00, writes: 166887.05, response time: 2.84ms (95%), errors: 0.00, reconnects: 0.00
    [ 212s] threads: 128, tps: 56106.98, reads: 0.00, writes: 168388.94, response time: 2.78ms (95%), errors: 0.00, reconnects: 0.00
    [ 213s] threads: 128, tps: 55713.91, reads: 0.00, writes: 167116.74, response time: 2.86ms (95%), errors: 1.00, reconnects: 0.00
    [ 214s] threads: 128, tps: 56372.98, reads: 0.00, writes: 169113.93, response time: 2.79ms (95%), errors: 0.00, reconnects: 0.00
    [ 215s] threads: 128, tps: 33603.03, reads: 0.00, writes: 100842.09, response time: 2.89ms (95%), errors: 0.00, reconnects: 0.00
    [ 216s] threads: 128, tps: 55810.99, reads: 0.00, writes: 167349.96, response time: 2.83ms (95%), errors: 0.00, reconnects: 0.00
    [ 217s] threads: 128, tps: 55921.95, reads: 0.00, writes: 167836.84, response time: 2.83ms (95%), errors: 0.00, reconnects: 0.00
    [ 218s] threads: 128, tps: 56273.13, reads: 0.00, writes: 168774.40, response time: 2.77ms (95%), errors: 0.00, reconnects: 0.00
    [ 219s] threads: 128, tps: 43009.21, reads: 0.00, writes: 129257.62, response time: 2.85ms (95%), errors: 0.00, reconnects: 0.00
    [ 220s] threads: 128, tps: 36798.79, reads: 0.00, writes: 110198.36, response time: 2.81ms (95%), errors: 0.00, reconnects: 0.00
    [ 221s] threads: 128, tps: 56222.09, reads: 0.00, writes: 168651.28, response time: 2.79ms (95%), errors: 0.00, reconnects: 0.00
    可以发现我们推理的一样，并且没有跌零了，没有跌零是因为我们的binlog日志文件变小了，下刷到磁盘的压力变小的，不断减少binlog日志的效果类似我们调整sync_binlog，不断缩短刷盘的时间，但是每次需要刷的内容就会变少，IO效率会变低。
    完结。