mysql服务抖动_MySQL的ALTER空表导致业务曲线抖动问题源码剖析

背景

长久以来，DBA苦DDL久矣。哪里有DDL，哪里就有DBA。有过几年经验的老司机，每次面试，都大概率会瞎扯什么各种DDL工具的奇技淫巧。但在笔者的工作环境中，由于分库分表技术的成熟，一键操作，从来不是梦。因为，我们只需要调整未来的空表。但是正是这种简单粗暴的操作，让笔者打脸了。直接在原生的MySQL中执行ALTER语句加两个字段，而且是一张张空表，业务请求量也不高，一秒一个ALTER。遗憾的是，业务曲线还是惊人的抖动了，简直没法玩啊。

源码分析

老规矩，先上火焰图，如下，ALTER语句

重点关注如下，

Sql_cmd_alter_table::execute: 2060 samples, 32.54% // 一般的alter table语句入口函数buf_flush_or_remove_pages: 671 samples, 10.60% + 684 samples 10.80% = 21.40%

// 用于在指定的缓冲池实例中删除指定表的脏页buf_pool_get_dirty_pages_count: 644 samples, 10.17%

// 用于统计缓冲池实例中指定表的脏页数

两者占比(21.40%+10.17%)/32.54%=97.0%，即几乎所有的时间都消耗在此。buf_flush_or_remove_pages函数梳理

// 在函数外层先获取缓冲池实例互斥锁

buf_flush_list_mutex_enter(buf_pool) // 获取flush_list_mutex互斥锁

rescan: // 用于重新遍历，注意会持续持有flush_list_mutex互斥锁

for (bpage = UT_LIST_GET_LAST(buf_pool->flush_list);bpage != NULL;bpage = prev)

// 从flush链表最后一块脏页开始往前遍历

>>if ((observer != NULL && observer != bpage->flush_observer) // 当前脏页的flush监听器不是要flush的监听器

>>|| (observer == NULL && id != bpage->id.space())) // 当前脏页所在的表不是要flush的表

>>>>// 直接跳过，往前找下一块脏页

>>else if (!buf_flush_or_remove_page(buf_pool, bpage, flush))

// 从缓冲池实例中删除该脏页或者把脏页刷盘，flush为true表示刷盘

>>>>all_freed = false // 用于返回脏页删除或者刷盘失败

>>else if (flush) // 需要把脏页刷盘

>>>>goto rescan // 重新开始遍历

>>++processed // 累加处理页数

>>if (buf_flush_try_yield(buf_pool, prev, processed))

// 如果遍历页数超过BUF_LRU_DROP_SEARCH_SIZE(1024)，则yield，暂时释放flush_list_mutex互斥锁

>>>>processed = 0 // 重置处理页数

buf_flush_list_mutex_exit(buf_pool) // 释放flush_list_mutex互斥锁

分析：很显然，对于一个空表来说，直接满足第一个条件，快速地跳过，直接找下一块脏页；从这里面的逻辑可以看到，对于有脏页的表来说，每次刷盘后又会继续重新开始遍历，直到最后缓冲池实例没有该表的脏页为止，这期间会一直持有flush链表的互斥锁；如果缓冲池实例脏页太多，该遍历并不会一直持续占有flush链表互斥锁，而是每遍历1024块脏页就会停下来，释放互斥锁，免得长时间占用，但是缓冲池实例互斥锁却会一直持有。buf_pool_get_dirty_pages_count函数梳理

buf_pool_mutex_enter(buf_pool) // 获取缓冲池实例互斥锁

buf_flush_list_mutex_enter(buf_pool) // 获取flush_list_mutex互斥锁

for (bpage = UT_LIST_GET_FIRST(buf_pool->flush_list);bpage != 0;bpage = UT_LIST_GET_NEXT(list, bpage))

// 从flush链表第一块脏页开始往后遍历

>>if ((observer != NULL && observer == bpage->flush_observer) // 当前脏页的flush监听器是要flush的监听器

>>|| (observer == NULL && id == bpage->id.space())) // 当前脏页所在的表是要flush的表

>>>>++count // 累加统计值

buf_flush_list_mutex_exit(buf_pool) // 释放flush_list_mutex互斥锁

buf_pool_mutex_exit(buf_pool) // 释放缓冲池实例互斥锁

分析：与前者不同的是，该函数只会获取缓冲池实例的互斥锁；其次，脏页统计是从第一块脏页开始遍历，中间会一直占用互斥锁，不会遍历了1024块页就暂停以释放锁资源。

进一步，观察此时的业务操作，INSERT语句UPDATE语句

重点关注如下，

Sql_cmd_insert::execute: 30 samples, 0.47% // 一般的insert语句入口函数

buf_flush_insert_into_flush_list: 10 samples, 0.16%

// 从“PolicyMutex >::enter”可以看到，卡在互斥锁等待

// 把一块脏页插入缓冲池实例的flush链表

Sql_cmd_update::execute: 17 samples, 0.27% // 一般的update语句入口函数

buf_LRU_buf_pool_running_out: 12 samples, 0.19%

// 从“PolicyMutex >::enter”可以看到，卡在互斥锁等待

// 遍历每个缓冲池实例，只要有free链表和LRU链表的可用页数与缓冲池实例总页数占比低于25%就退出buf_flush_insert_into_flush_list函数梳理

buf_flush_list_mutex_enter(buf_pool) // 获取flush_list_mutex互斥锁

block->page.oldest_modification = lsn // 设置缓存控制块对应脏页的日志序列号

UT_LIST_ADD_FIRST(buf_pool->flush_list, &block->page) // 把脏页的缓存控制块加入flush链表头部

incr_flush_list_size_in_bytes(block, buf_pool) // 增加flush链表大小(脏页块数)

buf_flush_list_mutex_exit(buf_pool) // 释放flush_list_mutex互斥锁

分析：对于INSERT语句来说，在它0.47%的执行时间(本身请求量并不高)里，有0.16%的时间消耗在了互斥锁等待，占比为0.16%/0.47%=34%；从代码层的分析可以看到，它卡在了获取flush_list_mutex互斥锁；虽然占比不到50%，但考虑到正常几乎可以忽略不计，占比0%，对于金融级DB来说，响应耗时是可以通过业务曲线体现出来的；由上面的分析，我们可以看到，缓冲池互斥锁是长时间占有的，而flush链表的互斥锁每遍历1024块缓存页就暂停，释放资源，以继续下次遍历。buf_LRU_buf_pool_running_out函数梳理

for (ulint i = 0; i < srv_buf_pool_instances && !ret; i++) // 遍历所有缓冲池实例

>>buf_pool_mutex_enter(buf_pool) // 获取缓冲池互斥锁

>>if (!recv_recovery_is_on() // 没有正在进行奔溃恢复应用redo记录

>>&& UT_LIST_GET_LEN(buf_pool->free) + UT_LIST_GET_LEN(buf_pool->LRU) < ut_min(buf_pool->curr_size, buf_pool->old_size) / 4)

// free链表与LRU链表页数总和小于缓冲池总页数的25%

>>>>ret = TRUE // 设置返回值为TRUE

>>buf_pool_mutex_exit(buf_pool) // 释放缓冲池互斥锁

分析：对于UPDATE语句来说，在它0.27%的执行时间(本身请求量不高)里，有0.19%的时间消耗在了互斥锁等待，占比为0.19%/0.27%=70.3%；从代码层的分析可以看到，它卡在了获取缓冲池互斥锁；考虑到正常几乎可以忽略不计，占比0%，此时业务曲线的响应耗时应该会出现相对更明显的抖动；由上面的分析，我们可以看到，缓冲池互斥锁是长期占有的，所以互斥锁的等待时间是INSERT语句的几倍是基本符合预期的。

现场取证

源码剖析了那么多，就差现场取证验证了。很显然，通过上面的分析，我们可以看到，大概率是跟flush链表有关的。因为flush链表越长，遍历时间越久。这个时候自然会想到经典的show engine innodb status命令，输出如下，

mysql> show engine innodb status\G

...

---BUFFER POOL 6Buffer pool size 163820

Free buffers 1024

Database pages 159205

Old database pages 58749

Modified db pages 66845

Pending reads 0

Pending writes: LRU 0, flush list 0, single page 0

Pages made young 18173000, not young 1732260318

0.00 youngs/s, 0.00 non-youngs/s

Pages read 50091719, created 3007094, written 67011530

0.00 reads/s, 0.00 creates/s, 0.00 writes/s

No buffer pool page gets since the last printout

Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s

LRU len: 159205, unzip_LRU len: 0

I/O sum[157]:cur[0], unzip sum[0]:cur[0]

---BUFFER POOL 7Buffer pool size 163820

Free buffers 1024

Database pages 159152

Old database pages 58729

Modified db pages 67400

Pending reads 0

Pending writes: LRU 0, flush list 0, single page 0

Pages made young 18254077, not young 1721813382

0.00 youngs/s, 0.00 non-youngs/s

Pages read 50635324, created 3009119, written 67599666

0.00 reads/s, 0.00 creates/s, 0.00 writes/s

No buffer pool page gets since the last printout

Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s

LRU len: 159152, unzip_LRU len: 0

I/O sum[157]:cur[0], unzip sum[0]:cur[0]

...

对于以上的输出，笔者是抱有疑问的，并不准确地清楚哪个值是flush链表。因为，依葫芦画瓢，根据“Modified db pages ”搜索代码，很快地找到了buf_print_io_instance函数，关键代码如下，

fprintf(file,

"Buffer pool size " ULINTPF "\n"

"Free buffers " ULINTPF "\n"

"Database pages " ULINTPF "\n"

"Old database pages " ULINTPF "\n"

"Modified db pages " ULINTPF "\n"

"Pending reads " ULINTPF "\n"

"Pending writes: LRU " ULINTPF

", flush list " ULINTPF

", single page " ULINTPF "\n",

pool_info->pool_size,

pool_info->free_list_len,

pool_info->lru_len,

pool_info->old_lru_len,

pool_info->flush_list_len,

pool_info->n_pend_reads,

pool_info->n_pending_flush_lru,

pool_info->n_pending_flush_list,

pool_info->n_pending_flush_single_page);

很显然，“Modified db pages ”对应的值就是flush链表的页数。对比其它的一些MySQL实例，我们可以发现，对于这些个别业务曲线抖动的MySQL来说，其flush链表，确实是过多的。

现场验证

调整刷新策略如下，innodb_max_dirty_pages_pct由60每次下调10，最终调整为30；innodb_max_dirty_pages_pct_lwm由0调整为默认的10。

mysql> show variables like '%dirty%';

+--------------------------------+-----------+| Variable_name | Value |

+--------------------------------+-----------+| innodb_max_dirty_pages_pct | 30.000000 |

| innodb_max_dirty_pages_pct_lwm | 10.000000 |

+--------------------------------+-----------+2 rows in set (0.00 sec)

观察IO平稳，脏页逐步减少，最终稳定如下，

mysql> show engine innodb status\G

...

---BUFFER POOL 6Buffer pool size 163820

Free buffers 1018

Database pages 159238

Old database pages 58762

Modified db pages 15369

Pending reads 0

Pending writes: LRU 0, flush list 0, single page 0

Pages made young 18794828, not young 1788067420

0.00 youngs/s, 37.48 non-youngs/s

Pages read 51775099, created 3129316, written 69586524

7.50 reads/s, 5.00 creates/s, 7.00 writes/s

Buffer pool hit rate 982 / 1000, young-making rate 0 / 1000 not 90 / 1000

Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s

LRU len: 159238, unzip_LRU len: 0

I/O sum[3841]:cur[10], unzip sum[0]:cur[0]

---BUFFER POOL 7Buffer pool size 163820

Free buffers 1011

Database pages 159156

Old database pages 58734

Modified db pages 15850

Pending reads 0

Pending writes: LRU 0, flush list 0, single page 0

Pages made young 18884607, not young 1778887831

0.50 youngs/s, 31.48 non-youngs/s

Pages read 52341983, created 3131053, written 70204239

7.00 reads/s, 3.50 creates/s, 7.00 writes/s

Buffer pool hit rate 981 / 1000, young-making rate 1 / 1000 not 87 / 1000

Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s

LRU len: 159156, unzip_LRU len: 0

I/O sum[3841]:cur[10], unzip sum[0]:cur[0]

...

此时，再重新进行DDL操作，业务曲线平稳，不再波动。

结论

对于一个ALTER空表操作来说，在缓冲池实例中脏页过多的情况下，大量的执行时间(本案例中占比97.0%)都将消耗在遍历脏页链表找出该表需要刷盘的脏页并进行刷盘以及统计缓冲池实例脏页链表中属于该表脏页数的过程中；而这两种操作，都无一例外地长期锁住缓冲池实例；对于前者，它还会短暂地锁住脏页链表，只不过每遍历1024块脏页，又通过看着类似协程操作来释放锁资源，下次接着遍历；对于INSERT语句来说，它锁住脏页链表的等待时间会明显延长，对于UPDATE语句，它可能会更加明显，因为它要锁住缓冲池实例。