這個(gè)問題是來自一位朋友，我通過pstack最終確認(rèn)問題，涉及到兩個(gè)參數(shù)的設(shè)置，我將從源碼進(jìn)行解釋，如果有誤還請(qǐng)見諒。

一、問題展示

1、簡(jiǎn)單插入需要1秒

語句截圖如下：

image.png

耗時(shí)截圖如下：

image.png

2、profile展示

image.png

實(shí)際上這里的query end是一個(gè)非常有用的信息，基本確認(rèn)是在order_commit函數(shù)上的等待。

二、問題初次分析

在我遇到的案例中有大事物造成的小事物commit慢的情況，且狀態(tài)也是query end，但是這里問題顯然不太一樣，如果是大事物造成的會(huì)是偶爾出現(xiàn)commit慢的情況而這里是穩(wěn)定出現(xiàn)等待1秒的情況。但是我還是要朋友采集了binlog的大事物信息使用我的一個(gè)工具如下:

小工具可以分析binlog 的一些信息比如：
1、是否有長(zhǎng)期未提交的事物 
2、是否有大事物 
3、每個(gè)表生成了多少日志 
4、生成速度。
使用:
./infobin  mysql-bin.001793 20 2000000 10 -t >log1793.log

第一個(gè)20 是分片數(shù)量
第二個(gè)2000000 是大于2M左右的事物定義為大事物
第三個(gè)10 是大于10秒未提交的事物定義為長(zhǎng)期未提交的事物 
下載地址:
http://pan.baidu.com/s/1jHIWUN0

只能用于binlog 不能用于relaylog。最好將binlog拷貝其他機(jī)器執(zhí)行，不要在生產(chǎn)服務(wù)器跑
最好是5.6 5.7 row格式binlog

這個(gè)工具是我用C寫的不依賴其他工具解析binlog獲取有用信息的工具，也很多朋友在用。占時(shí)沒有開源，其實(shí)也很簡(jiǎn)單就是分析binlog的event來獲取有用信息。
得到的簡(jiǎn)化結(jié)果如下:

-------------Now begin--------------
Check Mysql Version is:5.7.19-log
Check Mysql binlog format ver is:V4
Warning:Check This binlog is not closed!
Check This binlog total size:87546667(bytes)
Note:load data infile not check!
-------------Total now--------------
Trx total[counts]:42771
Event total[counts]:251792
Max 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)

實(shí)際上我們很容易看到binlog整個(gè)才80M左右確實(shí)包含一個(gè)大事物如下,大約占用了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)

但是大事物只會(huì)在提交的那一刻影響其他事物的提交且狀態(tài)為query end參考我早期的一篇文章
http://blog.itpub.net/7728585/viewspace-2133674/

我們先排除大事物導(dǎo)致的的問題。那么到底是什么問題呢，有朋友說可能是半同步，但是不使用半同步的情況下也一樣。且我覺得半同步的導(dǎo)致慢的狀態(tài)應(yīng)該不是query end 占時(shí)沒有測(cè)試。

三、確認(rèn)問題

沒有辦法只能使用pstack進(jìn)行分析，幸運(yùn)的是這個(gè)問題確實(shí)簡(jiǎn)單如下的pstack棧幀：

image.png

顯然我的猜測(cè)沒有問題確實(shí)是ordered_commit上出的問題，直接打開源碼找到如下：

/* Shall introduce a delay. */
  stage_manager.wait_count_or_timeout(opt_binlog_group_commit_sync_no_delay_count,
                                      opt_binlog_group_commit_sync_delay,
                                      Stage_manager::SYNC_STAGE);

這段代碼位于flush階段之后 sync階段之前，目的在于通過人為的設(shè)置delay來加大整個(gè)group commit組的事物數(shù)量，從而減少進(jìn)行磁盤刷盤sync的次數(shù)。這塊代碼雖然以前看過但是沒用過這兩個(gè)參數(shù)也就直接跳過了。

四、stage_manager.wait_count_or_timeout函數(shù)分析和參數(shù)分析

這個(gè)函數(shù)還是非常簡(jiǎn)單如下邏輯 看注釋即可:

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, //此處將等待時(shí)間分割 將使用 
                     max<ulong>(1, (to_wait * 0.1)));  //binlog_group_commit_sync_delay*0.1 和 1之間的 大的那個(gè)值作為時(shí)間分割 (單位 1/1000000 秒)
                                                       //binlog_group_commit_sync_delay是 (1000000)1秒則時(shí)間分割為0.1s(100000)
  while (to_wait > 0 && (count == 0 || static_cast<ulong>(m_queue[stage].get_size()) < count)) //進(jìn)行主體循環(huán)退出條件為 1、binlog_group_commit_sync_delay設(shè)置的時(shí)間消耗完
  {                                                                                             //2本組事物數(shù)量>binlog_group_commit_sync_no_delay_count 
    my_sleep(delta);//每次休眠delta時(shí)間如果是1秒則每次休眠0.1秒
    to_wait -= delta;//進(jìn)行總時(shí)間-delta 時(shí)間 
  }
}

從源碼我們分析一下參數(shù)binlog_group_commit_sync_delay和binlog_group_commit_sync_no_delay_count的含義:

• binlog_group_commit_sync_delay：通過人為的設(shè)置delay來加大整個(gè)group commit組的事物數(shù)量，從而減少進(jìn)行磁盤刷盤sync的次數(shù)，但是受到binlog_group_commit_sync_no_delay_count的限制,單位1/1000000秒。最大值1000000也就是1秒
• binlog_group_commit_sync_no_delay_count：如果delay的時(shí)間內(nèi)如果group commit中的事物數(shù)量達(dá)到了這個(gè)設(shè)置就直接跳出等待，而不需要等待binlog_group_commit_sync_delay的時(shí)間,單位group commit中事物的數(shù)量。

舉個(gè)列子比如我binlog_group_commit_sync_delay設(shè)置為10，binlog_group_commit_sync_no_delay_count設(shè)置為10，整個(gè)group commit將在這里等待，達(dá)到2個(gè)條件中的1個(gè)將會(huì)退出等待:

• 等待達(dá)到了1/100000 秒
• group commit中事物數(shù)量達(dá)到了10

四、問題庫設(shè)置

最后叫朋友查看了他們庫的設(shè)置如下:

image.png

居然binlog_group_commit_sync_delay設(shè)置為了最大值1000000也就是1秒，這也就解釋了為什么簡(jiǎn)單的insert都會(huì)等待1秒了，且狀態(tài)為query end。

五、總結(jié)

• 整個(gè)問題的排除最終還是依賴的pstack，這也再一次體現(xiàn)了它的重要性。棧幀是不會(huì)騙人的只有不懂的
• 要對(duì)query end代表的什么比較清楚
• 至此我知道了2種query end(或者顯示commit為starting)狀態(tài)下小事物提交慢的可能
  1、某個(gè)大事物提交引起偶爾的提交慢
  2、binlog_group_commit_sync_delay和binlog_group_commit_sync_no_delay_count 設(shè)置不正確引起提交慢