技術分享 | 巧用 binlog Event 發現問題

時間  2020-02-14 標籤 技術 分享 巧用 binlog event 發現問題
做者：高鵬（八怪）
文章末尾有他著做的《深刻理解 MySQL 主從原理 32 講》，深刻透徹理解 MySQL 主從，GTID 相關技術知識。

有了前面對 Event 的瞭解，咱們就能夠利用這些 Event 來完成一些工做了。我曾經在學習了這些經常使用的 Event 後，使用 C 語言寫過一個解析 Event 的工具，我叫它‘infobin’，意思就是從 binary log 提取信息的意思。據我所知雖然這個工具在少數狀況下會出現 BUG 可是仍是有些朋友在用。我這裏並非要推廣個人工具，而是要告訴你們這種思路。我是結合工做中遇到的一些問題來完成了這個工具的，主要功能包含以下：python

  • 分析 binary log 中是否有長期未提交的事務 ，長期不提交的事務將會引起更多的鎖爭用。
  • 分析 binary log 中是否有大事務 ，大事務的提交可能會堵塞其它事務的提交。
  • 分析 binary log 中每一個表生成了多少 DML Event，這樣就能知道哪一個表的修改量最大。
  • 分析 binary log 中 Event 的生成速度，這樣就能知道哪一個時間段生成的 Event 更多。
下面是這個工具的地址，供你們參考：
https://github.com/gaopengcar...

這個工具的幫助信息以下：mysql

[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 isprintout,the result will small
[[-force]]:force analyze if unkown error check!!

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

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

前面我已經屢次提到過對於一個手動提交的事務而言有以下特色，咱們以‘Insert’語句爲列：github

  1. GTID_LOG_EVENT 和 XID_EVENT 是命令‘COMMIT’發起的時間。
  2. QUERY_EVENT 是第一個‘Insert’命令發起的時間。
  3. MAP_EVENT/WRITE_ROWS_EVENT 是每一個‘Insert’命令發起的時間。

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

咱們來看看 Event 的順序和時間以下：shell

若是咱們使用最後一個 XID_EVENT 的時間減去 QUERY_EVENT 的時間，那麼這個事務從第一條語句開始到‘COMMIT’的時間就計算出來了。注意一點，實際上‘BEGIN’命令並無記錄到 Event 中，它只是作了一個標記讓事務不會自動進入提交流程。數據庫

關於‘BEGIN’命令作了什麼能夠參考個人簡書文章以下：
https://www.jianshu.com/p/6de...

2、分析大事務

這部分實現比較簡單，咱們只須要掃描每個事務 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 做爲大事務的定義比較合適，固然這個根據本身的需求進行計算。學習

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

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

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

這個功能也很是實用，經過這個分析咱們能夠知道數據庫中哪個表的修改量最大。實現方式主要是經過掃描 binary log 中的 MAP_EVENT 和接下來的 DML Event，經過 table id 獲取表名，而後將 DML Event 的大小納入這個表中，作一個鏈表，最後排序輸出就行了。
可是前面咱們說過 table id 即使在一個事務中也可能改變，這是我開始沒有考慮到的，所以這個工具備必定的問題，可是大部分狀況是能夠正常運行的。

5、工具展現

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

mysql> flush binary logs;
Query OK, 0 rows affected (0.51 sec)

mysql> select count(*) from tti;
+----------+
| count(*) |
+----------+
| 98304|
+----------+
1 row inset(0.06 sec)

mysql> deletefrom 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 inset(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.0000053100000015-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:[2019062514:00:08(CST)]
trx_end_time:[2019062514:00:39(CST)] trx_begin_pos:889067
trx_end_pos:889267 query_exe_time:0
--EveryTable binlog size(bytes) and times:
Note:size unit is bytes
---(1)CurrentTable: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)CurrentTable: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:[2019062514:00:08(CST)]
trx_end_time:[2019062514:00:39(CST)] trx_begin_pos:889067
trx_end_pos:889267 query_exe_time:0
  • 本 binary log 有兩個表的修改記錄 tti 和 tpp，其中 tti 表有‘Delete’操做和‘Insert’操做，tpp 表只有‘Insert’操做，而且包含了日誌量的大小。
--EveryTable binlog size(bytes) and times:
Note:size unit is bytes
---(1)CurrentTable: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)CurrentTable: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 去統計，可是這個工具的速度要遠遠快於這種方式。

最後推薦高鵬的專欄《深刻理解 MySQL 主從原理 32 講》，想要透徹瞭解學習 MySQL 主從原理的朋友不容錯過。

联系我们 沪ICP备2021010478号-7