共计 9616 个字符，预计需要花费 25 分钟才能阅读完成。
这篇文章主要介绍怎么通过 binlog 轻松的找到没有及时提交的事物，文中介绍的非常详细，具有一定的参考价值，感兴趣的小伙伴们一定要看完！
一、前言
以前我也写过一个帮助如下：
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 中如果我们显示的开启和提交一个事物如下:
begin;
insert XXX;
update XXX;
select XXX;
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 中会统计如下信息
Trx total[counts]: 总的事物个数
Event total[counts]: 总的 event 个数
Avg binlog size(/sec): 平均每秒生成的 binlog 大小
Avg binlog size(/min): 平均每分生成的 binlog 大小
–Piece view:
根据用户指定 piece 大小得到一个高度均衡直方图，这个直方图用于发现是否有某个时间段生成 binlog 特别大
–Large than xxx(bytes) trx:
大于 xxx BYTES 的事物，最后会有一个汇总，这部分给出了大事物的开始位置 trx_begin_p 结束的位置 trx_end_p
–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.logmysql-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 查吧！
以上是“怎么通过 binlog 轻松的找到没有及时提交的事物”这篇文章的所有内容，感谢各位的阅读！希望分享的内容对大家有帮助，更多相关知识，欢迎关注丸趣 TV 行业资讯频道！
