vc mysql insert_MySQL简单INSERT超慢原因排查

一、问题展示

1、简单插入需要1秒

语句截图如下：

MySQL简单INSERT超慢原因排查-1.jpg (42.25 KB, 下载次数: 0)

2018-10-11 09:48 上传

耗时截图如下：

MySQL简单INSERT超慢原因排查-2.jpg (38.24 KB, 下载次数: 0)

2018-10-11 09:48 上传

2、profile展示：

MySQL简单INSERT超慢原因排查-3.jpg (60.87 KB, 下载次数: 0)

2018-10-11 09:48 上传

实际上这里的query end是一个很是有用的信息，基本确认是在order_commit函数上的期待。

2、问题初度阐发

在我遇到的案例中有大事务造成的小事务commit慢的情况，且状态也是query end，可是这里问题显然不太一样，如果是大事务造成的会是偶尔呈现commit慢的情况而这里是稳定呈现期待1秒的情况。可是我还是要朋友收集了binlog的大事务信息使用我的一个工具如下:

MySQL简单INSERT超慢原因排查-4.jpg (31.61 KB, 下载次数: 0)

2018-10-11 09:48 上传

这个工具是我用C写的不依赖其他工具解析binlog获取有用信息的工具，也很多朋友在用。占时没有开源，其实也很简单就是阐发binlog的event来获取有用信息。

获得的简化结果如下:

-------------Now begin--------------Check Mysql Version is:5.7.19-logCheck Mysql binlog format ver is:V4Warning:Check This binlog is not closed!Check This binlog total size:87546667(bytes)Note:load data infile not check!-------------Total now--------------Trx total[counts]:42771Event total[counts]:251792Max trx event size:9268(bytes) Pos:78378238[0X4ABF4FE]Avg binlog size(/sec):16745.729(bytes)[16.353(kb)]Avg binlog size(/min):1004743.688(bytes)[981.195(kb)]...--Large than 2000000(bytes) trx:(1)Trx_size:54586527(bytes)[53307.156(kb)] trx_begin_p:359790[0X57D6E] trx_end_p:54946317[0X3466A0D]Total large trx count size(kb):#53307.156(kb)....---(79)Current Table:froad_cbank_anhui.cb_sms_log:: Insert:binlog size(824224(Bytes)) times(3135) Update:binlog size(2046042(Bytes)) times(3841) Delete:binlog size(0(Bytes)) times(0) Total:binlog size(2870266(Bytes)) times(6976)---(80)Current Table:test.2018products:: Insert:binlog size(54586359(Bytes)) times(6647) Update:binlog size(0(Bytes)) times(0) Delete:binlog size(0(Bytes)) times(0) Total:binlog size(54586359(Bytes)) times(6647)---Total binlog dml event size:73212228(Bytes) times(65090)实际上我们很容易看到binlog整个才80M左右确实包含一个大事务如下,大约占用了50M多。

--Large than 2000000(bytes) trx:(1)Trx_size:54586527(bytes)[53307.156(kb)] trx_begin_p:359790[0X57D6E] trx_end_p:54946317[0X3466A0D]Total large trx count size(kb):#53307.156(kb)

可是大事务只会在提交的那一刻影响其他事务的提交且状态为query end参考我早期的一篇文章：http://blog.itpub.net/7728585/viewspace-2133674/

我们先排除大事务致使的的问题。那么究竟是什么问题呢，有朋友说可能是半同步，可是不使用半同步的情况下也一样。且我觉得半同步的致使慢的状态应该不是query end 占时没有测试。

三、确认问题

没有体例只能使用pstack进行阐发，幸运的是这个问题确实简单如下的pstack栈帧：

MySQL简单INSERT超慢原因排查-5.jpg (46.98 KB, 下载次数: 0)

2018-10-11 09:48 上传

显然我的料想没有问题确实是ordered_commit上出的问题，直接打开源码找到如下：

MySQL简单INSERT超慢原因排查-6.jpg (20.61 KB, 下载次数: 0)

2018-10-11 09:48 上传

这段代码位于flush阶段之后 sync阶段之前，目的在于通过人为的设置delay来加大整个group commit组的事务数量，从而减少进行磁盘刷盘sync的次数。这块代码虽然以前看过可是没用过这两个参数也就直接跳过了。

四、stage_manager.wait_count_or_timeout函数阐发和参数阐发

这个函数还是很是简单如下逻辑 看注释即可:

void Stage_manager::wait_count_or_timeout(ulong count, ulong usec, StageID stage){ ulong to_wait= DBUG_EVALUATE_IF("bgc_set_infinite_delay", LONG_MAX, usec); /* For testing purposes while waiting for inifinity to arrive, we keep checking the queue size at regular, small intervals. Otherwise, waiting 0.1 * infinite is too long. */ ulong delta= DBUG_EVALUATE_IF("bgc_set_infinite_delay", 100000, //此处将期待时间朋分 将使用  max(1, (to_wait * 0.1))); //binlog_group_commit_sync_delay*0.1 和 1之间的 大的那个值作为时间朋分 (单位 1/1000000 秒) //binlog_group_commit_sync_delay是 (1000000)1秒则时间朋分为0.1s(100000) while (to_wait > 0 && (count == 0 || static_cast(m_queue[stage].get_size()) < count)) //进行主体循环退出条件为 1、binlog_group_commit_sync_delay设置的时间消耗完 { //2本组事务数量>binlog_group_commit_sync_no_delay_count  my_sleep(delta);//每次休眠delta时间如果是1秒则每次休眠0.1秒 to_wait -= delta;//进行总时间-delta 时间  }}

从源码我们阐发一下参数binlog_group_commit_sync_delay和binlog_group_commit_sync_no_delay_count的含义:

binlog_group_commit_sync_delay：通过人为的设置delay来加大整个group commit组的事务数量，从而减少进行磁盘刷盘sync的次数，可是受到binlog_group_commit_sync_no_delay_count的限制,单位1/1000000秒。最大值1000000也就是1秒

binlog_group_commit_sync_no_delay_count：如果delay的时间内如果group commit中的事务数量达到了这个设置就直接跳出期待，而不需要期待binlog_group_commit_sync_delay的时间,单位group commit中事务的数量。

举个列子好比我binlog_group_commit_sync_delay设置为10，binlog_group_commit_sync_no_delay_count设置为10，整个group commit将在这里期待，达到2个条件中的1个将会退出期待:

期待达到了1/100000 秒

group commit中事务数量达到了10

四、问题库设置

最后叫朋友查看了他们库的设置如下:

MySQL简单INSERT超慢原因排查-7.jpg (21.35 KB, 下载次数: 0)

2018-10-11 09:48 上传

居然binlog_group_commit_sync_delay设置为了最大值1000000也就是1秒，这也就解释了为什么简单的insert城市期待1秒了，且状态为query end。

五、总结

整个问题的排除最终还是依赖的pstack，这也再一次体现了它的重要性。栈帧是不会骗人的只有不懂的

要对query end代表的什么比较清楚

至此我知道了2种query end(或者显示commit为starting)状态下小事务提交慢的可能

1、某个大事务提交引起偶尔的提交慢

2、binlog_group_commit_sync_delay和binlog_group_commit_sync_no_delay_count 设置不正确引起提交慢

更多内容回复查看:

游客，如果您要查看本帖隐藏内容请回复