如何巧用Event發(fā)現(xiàn)問題

小編給大家分享一下如何巧用Event發(fā)現(xiàn)問題，相信大部分人都還不怎么了解，因此分享這篇文章給大家參考一下，希望大家閱讀完這篇文章后大有收獲，下面讓我們一起去了解一下吧！

如果圖片不能顯示可查看下面鏈接：
https://www.jianshu.com/p/d636215d767f

有了前面對(duì)Event的了解，我們就可以利用這些Event來完成一些工作了。我曾經(jīng)在學(xué)習(xí)了這些常用的Event后，使用C語言寫過一個(gè)解析Event的工具，我叫它‘infobin’，意思就是從binary log提取信息的意思。據(jù)我所知雖然這個(gè)工具在少數(shù)情況下會(huì)出現(xiàn)BUG但是還是有些朋友在用。我這里并不是要推廣我的工具，而是要告訴大家這種思路。我是結(jié)合工作中遇到的一些問題來完成了這個(gè)工具的，主要功能包含如下：

• 分析binary log中是否有長期未提交的事務(wù) ，長期不提交的事務(wù)將會(huì)引發(fā)更多的鎖爭用。

• 分析binary log中是否有大事務(wù) ，大事務(wù)的提交可能會(huì)堵塞其它事務(wù)的提交。

• 分析binary log中每個(gè)表生成了多少DML Event，這樣就能知道哪個(gè)表的修改量最大。

• 分析binary log中Event的生成速度，這樣就能知道哪個(gè)時(shí)間段生成的Event更多。

這個(gè)工具的幫助信息如下：

[root@gp1 infobin]#  ./infobin 
USAGE ERROR!
[Author]: gaopeng [QQ]:22389860 [blog]:http://blog.itpub.net/7728585/ 
--USAGE:./infobin binlogfile pieces bigtrxsize bigtrxtime [-t] [-force]
[binlogfile]:binlog file!
[piece]:how many piece will split,is a Highly balanced histogram,
        find which time generate biggest binlog.(must:piece<2000000)
[bigtrxsize](bytes):larger than this size trx will view.(must:trx>256(bytes))
[bigtrxtime](sec):larger than this sec trx will view.(must:>0(sec))
[[-t]]:if [-t] no detail is print out,the result will small
[[-force]]:force analyze if unkown error check!!

接下來我們具體來看看這幾個(gè)功能大概是怎么實(shí)現(xiàn)的。

一、分析長期未提交的事務(wù)

前面我已經(jīng)多次提到過對(duì)于一個(gè)手動(dòng)提交的事務(wù)而言有如下特點(diǎn)，我們以‘Insert’語句為列：

1. GTID_LOG_EVENT和XID_EVENT是命令‘COMMIT’發(fā)起的時(shí)間。

2. QUERY_EVENT是第一個(gè)‘Insert’命令發(fā)起的時(shí)間。

3. MAP_EVENT/WRITE_ROWS_EVENT是每個(gè)‘Insert’命令發(fā)起的時(shí)間。

那實(shí)際上我們就可以用（1）減去（2）就能得到第一個(gè)‘DML’命令發(fā)起到‘COMMIT’命令發(fā)起之間所消耗的時(shí)間，再使用一個(gè)用戶輸入?yún)?shù)來自定義多久沒有提交的事務(wù)叫做長期未提交的事務(wù)就可以了，我的工具中使用bigtrxtime作為這個(gè)輸入。我們來用一個(gè)例子說明，我們做如下語句：

我們來看看Event的順序和時(shí)間如下：
|Event|時(shí)間|
|—-|—-|
|GTID_LOG_EVENT|11:25:30|
|QUERY_EVENT|11:25:22|
|MAP_EVENT（第1個(gè)insert）|11:25:22|
|WRITE_ROWS_EVENT（第1個(gè)insert）|11:25:22|
|MAP_EVENT（第2個(gè)insert）|11:25:26|
|WRITE_ROWS_EVENT（第2個(gè)insert）|11:25:26|
|MAP_EVENT（第3個(gè)insert）|11:25:28|
|WRITE_ROWS_EVENT（第3個(gè)insert）|11:25:28|
|XID_EVENT|11:25:30|

如果我們使用最后一個(gè)XID_EVENT的時(shí)間減去QUERY_EVENT的時(shí)間，那么這個(gè)事務(wù)從第一條語句開始到‘COMMIT’的時(shí)間就計(jì)算出來了。注意一點(diǎn)，實(shí)際上‘BEGIN’命令并沒有記錄到Event中，它只是做了一個(gè)標(biāo)記讓事務(wù)不會(huì)自動(dòng)進(jìn)入提交流程，關(guān)于‘BEGIN’命令做了什么可以參考我的簡書文章如下：
https://www.jianshu.com/p/6de1e8071279

二、分析大事務(wù)

這部分實(shí)現(xiàn)比較簡單，我們只需要掃描每一個(gè)事務(wù)GTID_LOG_EVENT和XID_EVENT之間的所有Event將它們的總和計(jì)算下來，就可以得到每一個(gè)事務(wù)生成Event的大小（但是為了兼容最好計(jì)算QUERY_EVENT和XID_EVENT之間的Event總量）。再使用一個(gè)用戶輸入?yún)?shù)自定義多大的事務(wù)叫做大事務(wù)就可以了，我的工具中使用bigtrxsize作為這個(gè)輸入?yún)?shù)。

如果參數(shù)binlog_row_image參數(shù)設(shè)置為‘FULL’，我們可以大概計(jì)算一下特定表的每行數(shù)據(jù)修改生成的日志占用的大?。?/p>

• ‘Insert’和‘Delete’：因?yàn)橹挥衎efore_image或者after_image，因此100字節(jié)一行數(shù)據(jù)加上一些額外的開銷大約加上10字節(jié)也就是110字節(jié)一行。如果定位大事務(wù)為100M那么大約修改量為100W行數(shù)據(jù)。

• ‘Update’：因?yàn)榘琤efore_image和after_image，因此上面的計(jì)算的110字節(jié)還需要乘以2。因此如果定位大事務(wù)為100M那么大約修改量為50W行數(shù)據(jù)。

我認(rèn)為20M作為大事務(wù)的定義比較合適，當(dāng)然這個(gè)根據(jù)自己的需求進(jìn)行計(jì)算。

三、分析binary log中Event的生成速度

這個(gè)實(shí)現(xiàn)就很簡單了，我們只需要把binary log按照輸入?yún)?shù)進(jìn)行分片，統(tǒng)計(jì)結(jié)束Event和開始Event的時(shí)間差值就能大概算出每個(gè)分片生成花費(fèi)了多久時(shí)間，我們工具使用piece作為分片的傳入?yún)?shù)。通過這個(gè)分析，我們可以大概知道哪一段時(shí)間Event生成量更大，也側(cè)面反映了數(shù)據(jù)庫的繁忙程度。

四、分析每個(gè)表生成了多少DML Event

這個(gè)功能也非常實(shí)用，通過這個(gè)分析我們可以知道數(shù)據(jù)庫中哪一個(gè)表的修改量最大。實(shí)現(xiàn)方式主要是通過掃描binary log中的MAP_EVENT和接下來的DML Event，通過table id獲取表名，然后將DML Event的大小歸入這個(gè)表中，做一個(gè)鏈表，最后排序輸出就好了。但是前面我們說過table id即便在一個(gè)事務(wù)中也可能改變，這是我開始沒有考慮到的，因此這個(gè)工具有一定的問題，但是大部分情況是可以正常運(yùn)行的。

五、工具展示

下面我就來展示一下我說的這些功能，我做了如下操作：

mysql> flush binary logs;
Query OK, 0 rows affected (0.51 sec)
mysql> select count(*) from tti;
+----------+
| count(*) |
+----------+
|    98304 |
+----------+
1 row in set (0.06 sec)
mysql> delete from tti;
Query OK, 98304 rows affected (2.47 sec)
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> insert into tti values(1,'gaopeng');
Query OK, 1 row affected (0.00 sec)
mysql> select sleep(20);
+-----------+
| sleep(20) |
+-----------+
|         0 |
+-----------+
1 row in set (20.03 sec)
mysql> commit;
Query OK, 0 rows affected (0.22 sec)
mysql> insert into tpp values(10);
Query OK, 1 row affected (0.14 sec)

在示例中我切換了一個(gè)binary log，同時(shí)做了3個(gè)事務(wù)：

• 刪除了tti表數(shù)據(jù)一共98304行數(shù)據(jù)。

• 向tti表插入了一條數(shù)據(jù)，等待了20多秒提交。

• 向tpp表插入了一條數(shù)據(jù)。

我們使用工具來分析一下，下面是統(tǒng)計(jì)輸出：

./infobin mysql-bin.000005 3 1000000 15 -t > log.log
more log.log 
...
-------------Total now--------------
Trx total[counts]:3
Event total[counts]:125
Max trx event size:8207(bytes) Pos:420[0X1A4]
Avg binlog size(/sec):9265.844(bytes)[9.049(kb)]
Avg binlog size(/min):555950.625(bytes)[542.921(kb)]
--Piece view:
(1)Time:1561442359-1561442383(24(s)) piece:296507(bytes)[289.558(kb)]
(2)Time:1561442383-1561442383(0(s)) piece:296507(bytes)[289.558(kb)]
(3)Time:1561442383-1561442455(72(s)) piece:296507(bytes)[289.558(kb)]
--Large than 500000(bytes) trx:
(1)Trx_size:888703(bytes)[867.874(kb)] trx_begin_p:299[0X12B] 
trx_end_p:889002[0XD90AA]
Total large trx count size(kb):#867.874(kb)
--Large than 15(secs) trx:
(1)Trx_sec:31(sec)  trx_begin_time:[20190625 14:00:08(CST)] 
trx_end_time:[20190625 14:00:39(CST)] trx_begin_pos:889067
trx_end_pos:889267 query_exe_time:0 
--Every Table binlog size(bytes) and times:
Note:size unit is bytes
---(1)Current Table:test.tpp::
   Insert:binlog size(40(Bytes)) times(1)
   Update:binlog size(0(Bytes)) times(0)
   Delete:binlog size(0(Bytes)) times(0)
   Total:binlog size(40(Bytes)) times(1)
---(2)Current Table:test.tti::
   Insert:binlog size(48(Bytes)) times(1)
   Update:binlog size(0(Bytes)) times(0)
   Delete:binlog size(888551(Bytes)) times(109)
   Total:binlog size(888599(Bytes)) times(110)
---Total binlog dml event size:888639(Bytes) times(111)

我們發(fā)現(xiàn)我們做的操作都統(tǒng)計(jì)出來了：

• 包含一個(gè)大事務(wù)日志總量大于500K，大小為800K左右，這是我的刪除tti表中98304行數(shù)據(jù)造成的。

  --Large than 500000(bytes) trx:
  (1)Trx_size:888703(bytes)[867.874(kb)] trx_begin_p:299[0X12B] 
  trx_end_p:889002[0XD90AA]

• 包含一個(gè)長期未提交的事務(wù)，時(shí)間為31秒，這是我特意等待20多秒提交引起的。

  --Large than 15(secs) trx:
  (1)Trx_sec:31(sec)  trx_begin_time:[20190625 14:00:08(CST)]
  trx_end_time:[20190625 14:00:39(CST)] trx_begin_pos:889067
  trx_end_pos:889267 query_exe_time:0

• 本binary log有兩個(gè)表的修改記錄tti和tpp，其中tti表有‘Delete’操作和‘Insert’操作，tpp表只有‘Insert’操作，并且包含了日志量的大小。

--Every Table binlog size(bytes) and times:
Note:size unit is bytes
---(1)Current Table:test.tpp::
   Insert:binlog size(40(Bytes)) times(1)
   Update:binlog size(0(Bytes)) times(0)
   Delete:binlog size(0(Bytes)) times(0)
   Total:binlog size(40(Bytes)) times(1)
---(2)Current Table:test.tti::
   Insert:binlog size(48(Bytes)) times(1)
   Update:binlog size(0(Bytes)) times(0)
   Delete:binlog size(888551(Bytes)) times(109)
   Total:binlog size(888599(Bytes)) times(110)
---Total binlog dml event size:888639(Bytes) times(111)

好了到這里我想告訴你的就是，學(xué)習(xí)了Event過后就可以自己通過各種語言去試著解析binary log，也許你還能寫出更好的工具實(shí)現(xiàn)更多的功能。

當(dāng)然也可以通過mysqlbinlog 進(jìn)行解析后，然后通過shell/python去統(tǒng)計(jì)，但是這個(gè)工具的速度要遠(yuǎn)遠(yuǎn)快于這種方式。

以上是“如何巧用Event發(fā)現(xiàn)問題”這篇文章的所有內(nèi)容，感謝各位的閱讀！相信大家都有了一定的了解，希望分享的內(nèi)容對(duì)大家有所幫助，如果還想學(xué)習(xí)更多知識(shí)，歡迎關(guān)注億速云行業(yè)資訊頻道！