#巧用Event發現問題

---

歡迎關注我的《深入理解MySQL主從原理 32講 》，如下：

![image.png](https://upload-images.jianshu.io/upload_images/7398834-0ffa3bdc078cddf4.png?imageMogr2/auto-orient/strip%7CimageView2/2/w/1240)

如果圖片不能顯示可檢視下面連結： 
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更多。

下面是這個工具的地址，供大家參考（我已經很久沒更新了）：
https://github.com/gaopengcarl/infobin

這個工具的幫助資訊如下：
```
[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作為這個輸入。我們來用一個例子說明，我們做如下語句：

|語句|時間| 
|---|---|
|begin|T1|
|insert into testrr values(20);|11:25:22|
|insert into testrr values(30);|11:25:26|
|insert into testrr values(40);|11:25:28|
|commit;|11:25:30|

我們來看看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去統計，但是這個工具的速度要遠遠快於這種方式。

---
第12節結束

第12節巧用Event發現問題

相關文章

第12節 巧用Event發現問題

相關文章

第12節巧用Event發現問題