當前位置：首頁 > 运维知识 > 数据库 >内容正文

数据库

MySQL:简单insert 一秒原因排查

發布時間：2023/12/31 数据库 25 豆豆

生活随笔收集整理的這篇文章主要介紹了 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 inifinityto arrive, we keep checking the queue size at regular,small intervals. Otherwise, waiting 0.1 * infiniteis too long.*/ulong delta=DBUG_EVALUATE_IF("bgc_set_infinite_delay", 100000, //此處將等待時間分割將使用 max<ulong>(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<ulong>(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 設置不正確引起提交慢