如何通過binlog 輕鬆的找到沒有及時提交的事物(infobin工具)

工具獲取

https://pan.baidu.com/s/1jHIWUN0

一、前言

本文只是工具的展示，未過多介紹細節，如果要更多瞭解細節請參考MYSQL運維內參第21章，當然我也有閱讀並且從原始碼級
進行了驗證，同時在書中也有一個用shell寫成的指令碼進行長期未提交的事物，但是這裡我自己使用了自己的工具infobin。
以前我也寫過一個幫助如下：

http://blog.itpub.net/7728585/viewspace-2133985/ 

但是沒有包含最新的對長期不提交事物的查詢，因為這是我新加入的，這個功能會在本文描述

另外這裡涉及到比較重要的兩個binlog event及另外這裡涉及到比較重要的兩個binlog event及query event和xid event，參考的早期的文章

• 解析MYSQL BINLOG 二進位制格式(3)--QUERY_EVENT
  http://blog.itpub.net/7728585/viewspace-2133321/
• 解析MYSQL BINLOG 二進位制格式(7)--Xid_log_event/XID_EVENThttp://blog.itpub.net/7728585/viewspace-2133502/

當然這是一個系列如果有興趣可以全部看看

http://blog.itpub.net/7728585/viewspace-2133188/ 解析MYSQL BINLOG 二進位制格式(1)--準備工作 
http://blog.itpub.net/7728585/viewspace-2133189/ 解析MYSQL BINLOG 二進位制格式(2)--FORMAT_DESCRIPTION_EVENT 
http://blog.itpub.net/7728585/viewspace-2133321/ 解析MYSQL BINLOG 二進位制格式(3)--QUERY_EVENT 
http://blog.itpub.net/7728585/viewspace-2133429/ 解析MYSQL BINLOG 二進位制格式(4)--TABLE_MAP_EVENT 
http://blog.itpub.net/7728585/viewspace-2133463/ 解析MYSQL BINLOG 二進位制格式(5)--WRITE_ROW_EVENT 
http://blog.itpub.net/7728585/viewspace-2133469/ 解析MYSQL BINLOG 二進位制格式(6)--UPDATE_ROW_EVENT/DELETE_ROW_EVENT  
http://blog.itpub.net/7728585/viewspace-2133502/ 解析MYSQL BINLOG 二進位制格式(7)--Xid_log_event/XID_EVENT 
http://blog.itpub.net/7728585/viewspace-2133506/ 解析MYSQL BINLOG二進位制格式(8)--GTID_LOG_EVENT/ANONYMOUS_GTID_LOG_EVENT及其他 
http://blog.itpub.net/7728585/viewspace-2133534/ 解析MYSQL BINLOG二進位制格式(9)--infobin解析binlog幫助文件
http://blog.itpub.net/7728585/viewspace-2133537/ 解析MYSQL BINLOG二進位制格式(10)--問題解答 

二、工具設計思路

在innodb中如果我們顯示的開啟和提交一個事物如下:

1. begin;
2. insert XXX;
3. update XXX;
4. select XXX;
5. commit;

這是一個我們熟知的事物，在MYSQL BINLOG 行格式中(當然本工具也可以用於語句格式的binlog),
整個事物包含如下的event

• GTID EVENT
• --QUERY EVENT
• ----MAP EVENT
• ------WRITE EVENT(insert)
• ----MAP EVENT
• ------UPDATE_ROW_EVENT (update)
• ----(select 沒有binlog產生)
• XID EVENT (commit)

在每一個event中的header中存在4位元組的一個時間，這個時間是新紀元時間。
而這個時間來自於dispatch_command函式最開始的設定執行緒的中的一個set_time()
函式

start_utime= utime_after_lock= my_micro_time(); 

當發起commit命令後這個時間會記錄到XID EVENT中。那麼我們得到一個設計思路
我們可以用XID EVENT的時間-QUERY EVENT的時間來得到一個時間差為事物持續的時間
，但是要注意如果不是手動提交而是自動提交當然也就不存在沒有及時提交的事物了，
並且這裡使用QUERY EVENT而沒有使用GTID EVENT是為了相容5.6不開啟GTID的情況，
在5.7中即使不開啟GTID也會有匿名的GTID EVENT。

另外值得注意的一點就是即使一個事物持續時間很長，並不一定是沒有及時提交，可能
事物中包含了select語句這種不記錄binlog的語句，這種是通過binlog無法確定的，但是
我們至少可以將這種長時間未提交的事物中的DML語句找到交給開發進行分析到底是什麼
原因。

三、工具說明

此工具實際來自我早前學習binlog event的時候寫的工具infobin，這次由於線上出現了
大量未及時提交的事物，從而加入了新的功能。
本工具的幫助文件在

• http://blog.itpub.net/7728585/viewspace-2133985/

簡單的說本工具總共分為兩部分，分別叫做DETAIL和TOTAL

• 第一部分
  通過分析原生的MYSQL BINLOG進行逐條分析(常用的EVENT進行分析)，這部分
  叫做DETAIL部分
• 第二部分
  通過掃描到資料根據使用者的輸入資訊進行彙總得到TOTAL部分，在TOTAL中會統計如下資訊
  1. Trx total[counts]: 總的事物個數
  2. Event total[counts]: 總的event個數
  3. Avg binlog size(/sec):平均每秒生成的binlog大小
  4. Avg binlog size(/min):平均每分生成的binlog大小
  5. --Piece view:
     根據使用者指定piece大小得到一個高度均衡直方圖，這個直方圖用於發現是否有某個時間段生成binlog特別大
  6. --Large than xxx(bytes) trx:
     大於xxx BYTES的事物，最後會有一個彙總，這部分給出了大事物的開始位置trx_begin_p結束的位置trx_end_p
  7. --Large than xxx(secs) trx:
     大於xxx 秒的事物都會進行彙總，給出了開始時間trx_begin_time,結束時間trx_end_time，開始位置trx_query_pos
     結束位置trx_xid_pos,這個功能是我新加的。

有了binlog的開始和結束位置要找到是什麼DML語句就非常方便了如下就可以了

./mysqlbinlog mysql-bin.000274 --base64-output='decode-rows' -vv --start-position=592514409 --stop-position=592515464|more 

使用幫助

[dbadmin@bak ~]$ ./infobin 
[Author]: gaopeng [QQ]:22389860 [blog]:http://blog.itpub.net/7728585/ 
--USAGE:./infobin [binlogfile] [piece] [bigtrxsize] [bigtrxtime]
[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)) 

使用方法

./infobin mysql-bin.000274 2 200000 400  > log1.log 

• mysql-bin.000274:binlog名字
• 2:分為多少piece來統計生成直方圖
• 200000:事物大小 大於約200K的事物進行彙總
• 400:事物持續時間大於400秒的時間進行彙總

四、本工具的意義

本工具主要的意義包含4個方面

• 能夠更加清晰找到一個事物如下:

>Gtid Event:Pos:504(0X1f8) N_pos:569(0X239) Time:1496993578 Event_size:65(bytes) 
Gtid:89dfa8a4-cb13-11e6-b54-0c29a879a3:2
-->Query Event:Pos:569(0X239) N_Pos:641(0X281) Time:1496993578 Event_size:72(bytes) 
Exe_time:0  Use_db:test Statment(35b-trun):BEGIN /*!Trx begin!*/ Gno:2
---->Map Event:Pos641(0X281) N_pos:689(0X2b1) Time:1496993578 Event_size:48(bytes) 
TABLE_ID:142 DB_NAME:test TABLE_NAME:test Gno:2
------>Insert Event:Pos:689(0X2b1) N_pos:733(0X2dd) Time:1496993578 Event_size:44(bytes) 
Dml on table: test.test  table_id:142 Gno:2 
>Xid Event:Pos:733(0X2dd) N_Pos:764(0X2fc) Time:1496993578 Event_size:31(bytes) 
COMMIT; /*!Trx end*/ Gno:2 

顯然這是一個事物

• 能夠通過直方圖判斷binlog什麼時候生成量更大如下:

--Piece view:
(1)Time:1487560299-1487560543(244(s)) piece:107374204(bytes)[104857.625(kb)]
(2)Time:1487560543-1487560751(208(s)) piece:107374204(bytes)[104857.625(kb)]
(3)Time:1487560751-1487561012(261(s)) piece:107374204(bytes)[104857.625(kb)]
(4)Time:1487561012-1487561480(468(s)) piece:107374204(bytes)[104857.625(kb)]
(5)Time:1487561480-1487562682(1202(s)) piece:107374204(bytes)[104857.625(kb)]
(6)Time:1487562682-1487563492(810(s)) piece:107374204(bytes)[104857.625(kb)]
(7)Time:1487563492-1487563723(231(s)) piece:107374204(bytes)[104857.625(kb)]
(8)Time:1487563723-1487563951(228(s)) piece:107374204(bytes)[104857.625(kb)]
(9)Time:1487563951-1487564159(208(s)) piece:107374204(bytes)[104857.625(kb)]
(10)Time:1487564159-1487564409(250(s)) piece:107374204(bytes)[104857.625(kb)] 

一目瞭然1487560543-1487560751和1487564159-1487564409生成的binlog更大(注意是新紀元時間)

• 可以更加清楚有本binlog有哪些大事物如下:

--Large than 700000(bytes) trx:
(1)Trx_size:719621(bytes)[702.755(kb)] trx_begin_p:60579814[0X39C5FE6] trx_end_p:61299435[0X3A75AEB]
(2)Trx_size:719771(bytes)[702.901(kb)] trx_begin_p:177760551[0XA986927] trx_end_p:178480322[0XAA364C2]
(3)Trx_size:719779(bytes)[702.909(kb)] trx_begin_p:314334603[0X12BC5D8B] trx_end_p:315054382[0X12C7592E]
(4)Trx_size:719803(bytes)[702.933(kb)] trx_begin_p:317542845[0X12ED51BD] trx_end_p:318262648[0X12F84D78] 

大事物的意義不言而喻，因為在函式order_commit函式中其中的3個佇列FLUSH佇列、SYNC佇列、COMMIT佇列均是序列的
事物過大會堵塞全庫其他的事物提交(GROUP COMMIT)

• 可以更加清楚看到本binlog中有哪些未及時提交的事物如下:

--Large than 400(secs) trx:
(1)Trx_sec:406(sec)  trx_begin_time:1502441602 trx_end_time:1502442008 trx_query_pos:592514409 trx_xid_pos:592515464 query_exe_time:90 
(2)Trx_sec:411(sec)  trx_begin_time:1502441597 trx_end_time:1502442008 trx_query_pos:592518620 trx_xid_pos:592519666 query_exe_time:95 
(3)Trx_sec:407(sec)  trx_begin_time:1502441601 trx_end_time:1502442008 trx_query_pos:592528469 trx_xid_pos:592529524 query_exe_time:91 
(4)Trx_sec:538(sec)  trx_begin_time:1502441539 trx_end_time:1502442077 trx_query_pos:595102123 trx_xid_pos:595103178 query_exe_time:153 
(5)Trx_sec:531(sec)  trx_begin_time:1502441547 trx_end_time:1502442078 trx_query_pos:595141415 trx_xid_pos:595142470 query_exe_time:145 
(6)Trx_sec:443(sec)  trx_begin_time:1502441694 trx_end_time:1502442137 trx_query_pos:597451804 trx_xid_pos:597452859 query_exe_time:0 
(7)Trx_sec:546(sec)  trx_begin_time:1502441592 trx_end_time:1502442138 trx_query_pos:597531453 trx_xid_pos:597532508 query_exe_time:100 
(8)Trx_sec:468(sec)  trx_begin_time:1502441697 trx_end_time:1502442165 trx_query_pos:598471241 trx_xid_pos:598472296 query_exe_time:0 
(9)Trx_sec:515(sec)  trx_begin_time:1502441693 trx_end_time:1502442208 trx_query_pos:600613882 trx_xid_pos:600614928 query_exe_time:0 

這也是本次新加入的功能。也是為檢視長期不提交事物定做的。

五、對長期未提交事物的測試

比如我做如下一個事物:

flush binary logs;
begin;
insert into testgp values(10);
insert into testgp values(20);
select sleep(5) from testgp limit 2;
commit;
flush binary logs; 

輸出如下：

-------------Now begin--------------
Check Mysql Version is:5.7.13-log
Check Mysql binlog format ver is:V4
Check This binlog is closed!
Check This binlog total size:585(bytes)
Note:load data infile not check!
------------Detail now--------------
>Format description log Event:Pos:4(0X4) N_pos:123(0X7b) Time:1502678321 Event_size:119(bytes) 
>Previous gtid Event:Pos:123(0X7b) N_pos:194(0Xc2) Time:1502678321 Event_size:71(bytes) 
>Gtid Event:Pos:194(0Xc2) N_pos:259(0X103) Time:1502678332 Event_size:65(bytes) 
Gtid:4a6f2a67-5d87-11e6-a6bd-0c29a879a3:196824 last_committed=0  sequence_number=1
-->Query Event:Pos:259(0X103) N_Pos:331(0X14b) Time:1502678322 Event_size:72(bytes) 
Exe_time:0  Use_db:test Statment(35b-trun):BEGIN /*!Trx begin!*/ Gno:196824
---->Map Event:Pos331(0X14b) N_pos:380(0X17c) Time:1502678322 Event_size:49(bytes) 
TABLE_ID:294 DB_NAME:test TABLE_NAME:testgp Gno:196824
------>Insert Event:Pos:380(0X17c) N_pos:420(0X1a4) Time:1502678322 Event_size:40(bytes) 
Dml on table: test.testgp  table_id:294 Gno:196824 
---->Map Event:Pos420(0X1a4) N_pos:469(0X1d5) Time:1502678322 Event_size:49(bytes) 
TABLE_ID:294 DB_NAME:test TABLE_NAME:testgp Gno:196824
------>Insert Event:Pos:469(0X1d5) N_pos:509(0X1fd) Time:1502678322 Event_size:40(bytes) 
Dml on table: test.testgp  table_id:294 Gno:196824 
>Xid Event:Pos:509(0X1fd) N_Pos:540(0X21c) Time:1502678332 Event_size:31(bytes) 
COMMIT; /*!Trx end*/ Gno:196824
>Rotate log Event:Pos:540(0X21c) N_pos:585(0X249) Time:1502678332 Event_size:45(bytes) 
-------------Total now--------------
Trx total[counts]:1
Event total[counts]:10
Max trx event size:119(bytes) Pos:4[0X4]
Avg binlog size(/sec):53.182(bytes)[0.052(kb)]
Avg binlog size(/min):3190.909(bytes)[3.116(kb)]
--Piece view:
(1)Time:1502678321-1502678321(0(s)) piece:117(bytes)[0.114(kb)]
(2)Time:1502678321-1502678322(1(s)) piece:117(bytes)[0.114(kb)]
(3)Time:1502678322-1502678322(0(s)) piece:117(bytes)[0.114(kb)]
(4)Time:1502678322-1502678322(0(s)) piece:117(bytes)[0.114(kb)]
(5)Time:1502678322-1502678332(10(s)) piece:117(bytes)[0.114(kb)]
--Large than 200000(bytes) trx:
No trx find!
--Large than 8(secs) trx:
(1)Trx_sec:10(sec)  trx_begin_time:1502678322 trx_end_time:1502678332 trx_query_pos:259 trx_xid_pos:540 query_exe_time:0 

這裡我們看到了我們剛才做的沒有及時提交的事物

--Large than 8(secs) trx:
(1)Trx_sec:10(sec)  trx_begin_time:1502678322 trx_end_time:1502678332 trx_query_pos:259 trx_xid_pos:540 query_exe_time:0 

起始和結束位置有了直接mysqlbinlog查吧！

結束語

infobin工具只要拿到binlog就可以進行解析不依賴其他工具，確實比較方便，現在來說支援5.6,5.7 的binlog對relay log支援不好。

作者微信:

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/7728585/viewspace-2143512/，如需轉載，請註明出處，否則將追究法律責任。