如何巧用Event發現問題

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

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

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

• 分析binary log中是否有長期未提交的事務 ，長期不提交的事務將會引發更多的鎖爭用。

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

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

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

這個工具的幫助信息如下：

[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!!

接下來我們具體來看看這幾個功能大概是怎么實現的。

一、分析長期未提交的事務

前面我已經多次提到過對于一個手動提交的事務而言有如下特點，我們以‘Insert’語句為列：

1. GTID_LOG_EVENT和XID_EVENT是命令‘COMMIT’發起的時間。

2. QUERY_EVENT是第一個‘Insert’命令發起的時間。

3. MAP_EVENT/WRITE_ROWS_EVENT是每個‘Insert’命令發起的時間。

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

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

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

二、分析大事務

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

如果參數binlog_row_image參數設置為‘FULL’，我們可以大概計算一下特定表的每行數據修改生成的日志占用的大小：

• ‘Insert’和‘Delete’：因為只有before_image或者after_image，因此100字節一行數據加上一些額外的開銷大約加上10字節也就是110字節一行。如果定位大事務為100M那么大約修改量為100W行數據。

• ‘Update’：因為包含before_image和after_image，因此上面的計算的110字節還需要乘以2。因此如果定位大事務為100M那么大約修改量為50W行數據。

我認為20M作為大事務的定義比較合適，當然這個根據自己的需求進行計算。

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

這個實現就很簡單了，我們只需要把binary log按照輸入參數進行分片，統計結束Event和開始Event的時間差值就能大概算出每個分片生成花費了多久時間，我們工具使用piece作為分片的傳入參數。通過這個分析，我們可以大概知道哪一段時間Event生成量更大，也側面反映了數據庫的繁忙程度。

四、分析每個表生成了多少DML Event

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

五、工具展示

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

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)

在示例中我切換了一個binary log，同時做了3個事務：

• 刪除了tti表數據一共98304行數據。

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

• 向tpp表插入了一條數據。

我們使用工具來分析一下，下面是統計輸出：

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

我們發現我們做的操作都統計出來了：

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

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

• 包含一個長期未提交的事務，時間為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有兩個表的修改記錄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)

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

當然也可以通過mysqlbinlog 進行解析后，然后通過shell/python去統計，但是這個工具的速度要遠遠快于這種方式。

以上是“如何巧用Event發現問題”這篇文章的所有內容，感謝各位的閱讀！相信大家都有了一定的了解，希望分享的內容對大家有所幫助，如果還想學習更多知識，歡迎關注億速云行業資訊頻道！