【MySQL】MySQL 8.0 redo log写入性能问题分析

最近对比了MySQL 5.6和8.0在8核环境下oltp_write_only的性能，发现8.0写入性能（QPS 6-7万）反而低于5.6版本的（QPS 14万），所以进一步测试分析了下redo log这里可能导致性能降低的原因，整理记录一下

1. 测试方法

sysbench –mysql-host=IP –mysql-port=PORT –mysql-user=mysql –mysql-password=PASSWD –tables=250 –table_size=25000 –db_driver=mysql –threads=128 –report-interval=5 –rand-type=uniform prepare

sysbench –mysql-host=IP –mysql-port=PORT –mysql-user=mysql –mysql-password=PASSWD –tables=250 –table_size=25000 –db_driver=mysql –threads=128 –report-interval=5 –rand-type=uniform –max-time=360 –max-requests=3000000 run

sysbench –mysql-host=IP –mysql-port=PORT –mysql-user=mysql –mysql-password=PASSWD –table_size=25000 –db_driver=mysql –threads=128 cleanup

2. 测试结果

1. upstream 8.0 (8核）

SQL statistics:
    queries performed:
        read:                            0
        write:                           12000000
        other:                           6000000
        total:                           18000000
    transactions:                        3000000 (10792.71 per sec.)
    queries:                             18000000 (64756.24 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)

General statistics:
    total time:                          277.9637s
    total number of events:              3000000

CPU:

2. upstream 8.0（8核，CPU 8专门跑log_writer，其余线程跑在1-7）

SQL statistics:
    queries performed:
        read:                            0
        write:                           12000000
        other:                           6000000
        total:                           18000000
    transactions:                        3000000 (10705.28 per sec.)
    queries:                             18000000 (64231.71 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)

General statistics:
    total time:                          280.2336s
    total number of events:              3000000

CPU:

3. upstream 8.0（8核，CPU 8专门跑log_flusher，其余线程跑1-7）

SQL statistics:
    queries performed:
        read:                            0
        write:                           12000000
        other:                           6000000
        total:                           18000000
    transactions:                        3000000 (12860.01 per sec.)
    queries:                             18000000 (77160.08 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)

General statistics:
    total time:                          233.2794s
    total number of events:              3000000

CPU:

4. upstream 8.0（8核，CPU 8专门用来跑log_writer和log_flusher，其余线程跑在1-7)

SQL statistics:
    queries performed:
        read:                            0
        write:                           12000000
        other:                           6000000
        total:                           18000000
    transactions:                        3000000 (15305.69 per sec.)
    queries:                             18000000 (91834.11 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)

General statistics:
    total time:                          196.0038s
    total number of events:              3000000

CPU:

3. 结果分析

1. 不做任何隔离时，8核均无法跑不到100%，性能较低，QPS 64756.24
2. 只隔离log_writer时，单独跑log_writer的核可以接近100%，但剩余7核不行，性能没有提升， QPS 64231.71
3. 只隔离log_flusher时8核可以都大于90%，性能有所提升，QPS 77599.04
4. 同时隔离log_writer和log_flusher时8核可以都接近100%，性能进一步提升，QPS 91834.11

从上面的结果可以看出来，

1. log_flusher是否隔离对8核CPU利用率的影响较大，分析原因应该是在不隔离log_flusher时，由于和很多用户线程共享CPU，所以log_flusher得不到有效的CPU调度无法充分执行，flush_to_disk_lsn更新滞后反过来又影响到用户线程的推进（innodb_flush_log_at_trx_commit = 1），所以整体CPU利用率上不去。隔离log_flusher之后，CPU和性能都有所提升，但相比同时隔离log_writer和log_flusher又有低一些
2. 单独隔离log_writer性能没有提升，分析原因应该还是同上，瓶颈在log_flusher上

综上，关于upstream 8.0写入性能较低的原因推测是log_writer和log_flusher由于和大量用户线程共享CPU核心，得不到充分调度成为瓶颈，影响整体写入性能，并且log_flusher更为严重。

4. 进一步验证

为了进一步验证上面的推测，我使用sysbench –max-requests=3000000分别对如下4中场景：

a.不隔离
b.同时隔离log_writer及log_flusher
c.单独隔离log_writer
d.单独隔离log_flusher

进行等量压测，每次都是300万次请求，另外为了LSN的可比较性，关掉了undo purge，基于此，我在sysbench run阶段对InnoDB log module进行打点记录，下面分组来看具体性能和打点信息：

性能

由于关掉了undo purge，除场景b外，其他场景QPS相较于之前的测试有所提升是符合预期的

打点信息

1. LSN

同样由于关掉了undo purge，对于sysbench –max-requests=3000000，lsn差不多

2. Buffer Wait

上面的这4个监控信息都是

mtr_t::commit()->
mtr_t::Command::execute()->
log_buffer_reserve()->
log_wait_for_space_after_reserving()->
log_wait_for_space_in_log_buf()->
log_write_up_to(flush_to_disk=false)->
log_wait_for_write()

里的打点，它们全为0，也就是说明配置使用的64M大小log buffer是够用的，无论隔离与否，都不会出现因为log buffer不够用而进行回收时的wait

3. recent_XXX

1. log_on_recent_written_wait_loops是在

mtr_t::commit()->
mtr_t::Command::execute()->
mtr_write_log_t::()->
log_buffer_write_completed()

里如果由于recent_written不足等待回收则进行的打点

1. log_on_recent_closed_wait_loops是在

mtr_t::commit()->
mtr_t::Command::execute()->
mtr_write_log_t::()->
log_wait_for_space_in_log_recent_closed()

里如果由于recent_closed不足等待回收则进行的打点

它们都为0说明recent_written和recent_closed当前配置够用，并且log_writer和log_closer对其回收及时。

重点关注下面的打点信息，首先先说下打点位置

4. Log Writes

1. log_write_requests是

mtr_t::commit()->
mtr_t::Command::execute()->
log_buffer_reserve()

里打点，可以看到mtr的个数也差不多

1. log_writes是

log_writer()->
log_writer_write_buffer()->
log_files_write_buffer()

里log_writer将log写进table cache并更新log_sys->write_lsn之后的打点

5. log_writer

1. log_writer_no_waits和log_writer_waits都是在

log_writer()->
os_event_wait_for(log.writer_event)

后的打点，log_writer_no_waits是在os_event_wait_for()时发现有连续可写的内容不需wait的次数，log_writer_waits是在os_event_wait_for()时发现没有连续可写的内容需要wait的次数

1. log_write_notifier_no_waits和log_write_notifier_waits都是在

log_write_notifier()->
os_event_wait_for(log.write_notifier_event)

后的打点，log_writer_no_waits是在os_event_wait_for()时发现log.write_lsn向前推进所以不需wait的次数，log_write_notifier_waits是os_event_wait_for()时发现log.write_lsn没有向前推进所以需要wait的次数，待分析

1. log_on_write_no_waits和log_on_write_waits都是在

XXX->
log_write_up_to()->
log_wait_for_write()->
os_event_wait_for(log.write_events[])

后的打点，可以看到都为0，说明并不存在用户线程在等待log_writer更新log.write_lsn到指定lsn的时候。

6. log_flusher

1. log_flusher_no_waits、log_flusher_waits和log_flusher_wait_loops都是在

log_flusher()->
os_event_wait_for(log.flusher_event)

后的打点，log_flusher_no_waits是在os_event_wait_for()时发现log.write_lsn向前推进所以不需要wait的次数，

log_flusher_waits是在os_event_wait_for()时发现log.write_lsn没有向前推进所以需要wait的次数，log_flusher_wait_loops则是在wait里被唤醒或timeout之后发现condition还不满足而继续wait的loop次数

1. log_flush_notifier_no_waits和log_flush_notifier_waits都是在

log_flush_notifier()->
os_event_wait_for(log.flush_notifier_event)

后的打点，log_flush_notifier_no_waits是在os_event_wait_for()时发现log.flushed_to_disk_lsn更新所以不需要wait的次数，log_flush_notifier_waits是在os_event_wait_for()时发现log.flushed_to_disk_lsn没更新所以需要wait的次数

1. log_on_flush_no_waits、log_on_flush_waits和log_on_flush_wait_loops都是在

XXX->
log_write_up_to(flush_to_disk=true)->
log_wait_for_flush()

后的打点，这里是用户线程在（innodb_flush_log_at_trx_commit = 1）等待flush_to_disk_lsn更新到自己对应的LSN，log_on_flush_no_waits是当用户线程对应的LSN的redo log已被log_flusher刷盘，无需wait的次数，log_on_flush_waits是当用户线程对应LSN的暂未不刷盘，需要wait的次数，log_on_flush_wait_loops是在wait中被唤醒或timeout后发现condition还不满足继续wait的loop次数

1. log_flush_lsn_avg_rate是每30次flush的内容平均每秒的长度
2. log_flush_total_time是整体flush的用时
3. log_flush_avg_time单次flush的平均用时

基于以上信息，分析如下，以a.不隔离作为基准

1. 隔离log_flusher(场景d)，可以看到隔离log_flusher之后，由于log_flusher独占1个核心，此时log_flusher_no_waits从219898增长到843696（4倍），说明log_flusher被调度执行到的次数更多，刷盘更及时，甚至因为CPU太过充分导致log_flusher_waits、log_flusher_wait_loops出现大幅增长。而log_on_flush_no_waits和log_on_flush_waits没有太大变化说明即使刷盘效率有所提高，但用户线程在自己对应LSN刷盘时还是需要等待，不过log_on_flush_wait_loops有所减少，从8616066减少到6954663，虽然wait次数没变，但wait里的loop变少，说明一定程度上用户线程推进速度还是有所提升，这点也符合QPS和CPU利用率提升的现象。另外log_flusher大约100万次（log_flusher_no_waits+log_flusher_waits）的刷盘操作，总用时30s，单次刷盘25us，效率最高。不过为什么整体性能提升有限呢？因为此时log_writer成为了瓶颈，此时CPU利用率有所提升，log_writer与大量用户线程共享核心，得不到充分调度，更新write_lsn不及时，这点可以从log_writer_no_waits和log_writes看出来，log_writer_waits没变的基础上，log_writer_no_waits从24110198降到3395741（1/6），正是因为隔离log_flusher后，用户线程CPU利用率有所提高（不隔离时会在等待自己对应LSN刷盘上wait较久，这样还会让出CPU给log_writer来用），log_writer拿不到CPU导致，对应的log_writes也从24891146降到4036257（1/6），log_writer的写入效率变低，瓶颈。
2. 隔离log_writer(场景c)，可以看到隔离log_writer之后，由于log_writer独占1个核心，此时log_writer_no_waits从24110198增长到38915995（近2倍），说明log_writer被调度到的次数更多，write_lsn推进更及时。而log_writer_waits没什么变化说明即使log_writer独占1个核心，CPU也是刚刚够用，基本每次写完page cache后就有新的log要再写入。不过log_on_flush_no_waits和log_on_flush_waits没有太大变化说明即使写page cache效率有所提高，但用户线程在等自己对应LSN刷盘时还是需要等待，不过log_on_flush_wait_loops有所减少，从8616066减少到6091019，一定程度上用户线程推进速度有所提升。至于整体性能提升不明显的原因，是因为此时log_flusher是瓶颈。按理说log_writer执行频率和效率大幅提高，唤醒log_flusher的频率也会很高，但log_flusher_no_waits从219898仅增长至353433（1.7倍，还不如隔离log_flusher带来的提升），log_flusher_waits甚至降低，另外可以看到log_flusher大约刷盘35万次，总用时210s，单次平均用时642us，（即使刨除由于单次fsync的内容变多导致可能的fsync用时变长之外）远高于隔离log_flusher时的用时，都说明此时log_flusher得不到有效的CPU调度，执行效率低下，瓶颈。
3. 同时隔离log_writer和log_flusher(场景b)，二者共用1个核心，此时log_flusher_no_waits从219898提升至4639077（23倍），被调度的更多，执行更充分，另外log_writer_no_waits没有太大变化（应该是log_flusher被调度更多了，执行效率变高，所以与其共享一个核心的log_writer相比不隔离时被调度的次数稍少一些），这样在log_writer执行效率没有太大变化的情况下，log_flusher效率大幅度提升，一共刷盘500万次，总用时138s，单次平均用时27us。这种情况，在log_on_flush_waits不变的基础上，log_on_flush_no_loops从8616066减少到3011060（1/3)，用户线程在等待自己LSN落盘的wait loops减少最多，所以整体性能也提升最多。

5. 其他发现

1. 在不做任何隔离的情况下，打开undo purge的性能低于关闭时的QPS，（64756.24 ： 78739.83），分析原因应该是打开undo purge时，由于undo purge truncate会写入更多的log，导致LSN变大（5736265204 ：7692486960），在插入这么多新的redo log后，由于log_flusher效率并没有提升，log变多了，用户线程在等待自己对应LSN刷盘时会等更久（log_on_flush_wait_loops变化，13015383 : 8616066），所以性能低一些。
2. 在32核，1024并发场景下，不隔离时QPS是274509.11，隔离时（log_writer和log_flusher同时绑定在CPU32）QPS反而降为254697.57，分析了下打点数据，隔离时log_writer_no_waits从8175104将为5261245，说明当在更多核心更高压力时，将log_writer、log_flusher同时放在一个核心会因为此时log_flusher相比不隔离时刷盘更快而导致log_writer被调度执行的机会更少，log_writer成为瓶颈
3. 在2的场景下，进一步测试，保持用户使用的核心数不变（CPU 1-31），多加一个核心，将log_writer绑定CPU32，log_flusher绑定CPU33，发现此时性能和不隔离是差不太多（281093.45 ：274509.11），分析打点数据，此时log_writer_no_waits(11153587)和log_flusher_no_waits(1600971)都大幅提升，说明二者并不是瓶颈（另外观察到此时log_flusher所在核心的CPU利用率也都有70%左右了），但性能为什么没上去呢？发现此时log_on_recent_closed_wait_loops从之前的0变成了17844432，证明用户线程在mtr::commit时等待recent_closed buffer回收空间次数变多，应该是此时log_writer写的更快，而log_closer由于与用户线程共享CPU，回收recent_closed不及时导致的，log_closer成为新的瓶颈
4. 在3的场景下，进一步测试，保持用户使用的核心数（CPU 1-31）和log_writer(CPU 32)和log_flusher（CPU32）不变的基础上，再加一个核心，绑定log_closer(CPU33)，此时性能提升较多310020.40，不过此时log_on_recent_closed_wait_loops并不为0（758048），因为log_closer并不是由谁唤醒而是周期性的执行，所以在这种情况下，默认的sleep时间(1000us）也显得太久，需要调小
5. 在2的场景下，只是用32个核心，用户线程使用（1-29），log_flusher、log_writer、log_closer使用（30-32），这样即使用户线程使用的核心相比场景2少了2个，但整体性能是299089.22，相比场景2反而有所提升

6. 总结

MySQL 8.0将写redo log拆分成多个线程异步来做的方式，可能并不是理想的优化，

1. 当并发比较低（用户线程少）时，用户线程与这些异步线程之间的交互等待反而不如直接像RocksDB那样全有用户线程来做更核实
2. 在并发比较高（用户线程多）时，又会因为这些异步线程（log_writer、log_flusher、log_closer）得不到充分的CPU调度而成为写入瓶颈。这样的异步设计需要确保这些异步线程有足够的CPU时间才能提高性能

所以目前我能想到的改进方案有如下2种：

1. 提高log异步线程的优先级
2. 使用RocksDB写WAL的做法，不过暂时还不确定，目前个人觉得这种一把梭实现没有什么硬伤，反而更好