MySQL:簡單insert 一秒原因排查

這個問題是來自一位朋友@春波，我透過pstack最終確認問題，涉及到兩個引數的設定，我將從原始碼進行解釋，如果有誤還請見諒。

---

一、問題展示

1、簡單插入需要1秒

語句截圖如下：

耗時截圖如下：

2、profile展示

實際上這裡的query end是一個非常有用的資訊，基本確認是在order_commit函式上的等待。

二、問題初次分析

在我遇到的案例中有大事物造成的小事物commit慢的情況，且狀態也是query end，但是這裡問題顯然不太一樣，如果是大事物造成的會是偶爾出現commit慢的情況而這裡是穩定出現等待1秒的情況。但是我還是要朋友採集了binlog的大事物資訊使用我的一個工具如下:

小工具可以分析binlog 的一些資訊比如： 1、是否有長期未提交的事物 2、是否有大事物 3、每個表生成了多少日誌 4、生成速度。
使用:
./infobin  mysql-bin.001793 20 2000000 10 -t >log1793.log 第一個20 是分片數量
第二個2000000 是大於2M左右的事物定義為大事物
第三個10 是大於10秒未提交的事物定義為長期未提交的事物 
下載地址:
http://pan.baidu.com/s/1jHIWUN0 只能用於binlog 不能用於relaylog。最好將binlog複製其他機器執行，不要在生產伺服器跑
最好是5.6 5.7 row格式binlog 

這個工具是我用C寫的不依賴其他工具解析binlog獲取有用資訊的工具，也很多朋友在用。佔時沒有開源，其實也很簡單就是分析binlog的event來獲取有用資訊。
得到的簡化結果如下:

-------------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) 

實際上我們很容易看到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棧幀：

顯然我的猜測沒有問題確實是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階段之前，目的在於透過人為的設定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

四、問題庫設定

最後叫朋友檢視了他們庫的設定如下:

居然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 設定不正確引起提交慢