最近碰到有台MySQL实例出现了MySQL服务短暂hang死,表现为瞬间的并发线程上升,连接数暴增。
排查Error Log文件中有page_cleaner超时的信息,引起我们的关注:
2019-08-24T23:47:16.211740+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4849ms. The settings might not be optimal. (flushed=240 and evicted=0, during the time.)
2019-08-24T23:47:23.362286+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 6151ms. The settings might not be optimal. (flushed=215 and evicted=0, during the time.)
【问题分析】 1、 error log中page_cleaner信息是如何产生的
通过源码storage/innobase/buf/buf0flu.cc可以看出,当满足curr_time > next_loop_time + 3000条件(大于4秒)时,会打印上面信息到error log中。next_loop_time为1000ms,即1秒钟做一次刷新页的操作。
if (ret_sleep == OS_SYNC_TIME_EXCEEDED) { ulint curr_time = ut_time_ms(); if (curr_time > next_loop_time + 3000) { if (warn_count == 0) { ib::info() n_flushed_last n_evicted 300) { warn_interval = 600; } else { warn_interval *= 2; } warn_count = warn_interval; } else { --warn_count; } } else { /* reset counter */ warn_interval = 1; warn_count = 0; } next_loop_time = curr_time + 1000; n_flushed_last = n_evicted = 0; }后半部分(flushed=182 and evicted=0, during the time.)日志,对应n_flushed_last和n_evicted两个变量,这两个变量来自于下面2个变量。
n_flushed_last += n_flushed_list;
从源码注释中可以看出,n_flushed_lru表示从LRU list尾部刷新的页数,也就是日志中如evicted=0指标的所表示的值。
n_flushed_list:这个是从flush_list刷新列表中刷新的页数,也就是脏页数,日志中flushed=182的值。
从pc_wait_finished函数可以看出page_cleaner线程包含了LRU list和flush_list两部分刷新,而且需要等待两部分都完成刷新。
2、MySQL5.7.4引入了多线程page cleaner,但由于LRU列表刷新和脏页列表刷新仍然耦合在一起,在遇到高负载,或是热数据的buffer pool instance时,仍存在性能问题。1) LRU List刷脏在先,Flush list的刷脏在后,但是是互斥的。也就是说在进Flush list刷脏的时候,LRU list不能继续去刷脏,必须等到下一个循环周期才能进行。
2) 另外一个问题是,刷脏的时候,page cleaner coodinator会等待所有的page cleaner线程完成之后才会继续响应刷脏请求。这带来的问题就是如果某个buffer pool instance比较热的话,page cleaner就不能及时进行响应。
Percona版本对LRU list刷脏做了很多优化。
mysqlbinlog -vvv binlog --start-datetime='2019-08-24 23:46:15' --stop-datetime='2019-08-24 23:47:25'|less
从计数器指标可以看出期间并发线程积压,QPS处理能力下降,稍后MySQL服务恢复,积压的请求集中释放,导致并发连接进一步上升
可能期间LRU list的mutex资源锁定,导致page cleaner线程在LRU list刷新时阻塞,从而表现出page_cleaner线程执行时间过长。
innodb_buffer_pool_pages_misc与adaptive hash index有关,下面是官网的描述
The number of pages in the InnoDB buffer pool that are busy because they have been allocated for administrative overhead, such as row locks or the adaptive hash index. This value can also be calculated as Innodb_buffer_pool_pages_total − Innodb_buffer_pool_pages_free − Innodb_buffer_pool_pages_data. When using compressed tables, Innodb_buffer_pool_pages_misc may report an out-of-bounds value (Bug #59550).
5、为什么AHI短时间内会释放大量的内存呢,通过慢查询日志我们排查到期间有drop table的操作,但drop的表容量约50G,并不是很大,drop table为什么会导致MySQL服务短暂hang死,它对服务器性能会产生多大的影响,我们做了模拟测试。 【测试重现过程】