记一次Mysql数据库性能异常抖动分析全过程

环境及测试现象

在同一个硬件环境下,相同的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效率会变低。
    完结。

标签: none

仅有一条评论

  1. yanyun yanyun

    小结:在sync_binlog参数设置为0的时候,如果max_binlog_size设置很大的话,就会有概率出现性能大幅波动现象,不过也要取决于磁盘瞬时的吞吐能力。

添加新评论