怎么通过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/解析MYSQLBINLOG二进制格式(1)--准备工作http://blog.itpub.net/7728585/viewspace-2133189/解析MYSQLBINLOG二进制格式(2)--FORMAT_DESCRIPTION_EVENThttp://blog.itpub.net/7728585/viewspace-2133321/解析MYSQLBINLOG二进制格式(3)--QUERY_EVENThttp://blog.itpub.net/7728585/viewspace-2133429/解析MYSQLBINLOG二进制格式(4)--TABLE_MAP_EVENThttp://blog.itpub.net/7728585/viewspace-2133463/解析MYSQLBINLOG二进制格式(5)--WRITE_ROW_EVENThttp://blog.itpub.net/7728585/viewspace-2133469/解析MYSQLBINLOG二进制格式(6)--UPDATE_ROW_EVENT/DELETE_ROW_EVENThttp://blog.itpub.net/7728585/viewspace-2133502/解析MYSQLBINLOG二进制格式(7)--Xid_log_event/XID_EVENThttp://blog.itpub.net/7728585/viewspace-2133506/解析MYSQLBINLOG二进制格式(8)--GTID_LOG_EVENT/ANONYMOUS_GTID_LOG_EVENT及其他http://blog.itpub.net/7728585/viewspace-2133534/解析MYSQLBINLOG二进制格式(9)--infobin解析binlog帮助文档http://blog.itpub.net/7728585/viewspace-2133537/解析MYSQLBINLOG二进制格式(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语句就非常方便了如下就可以了
./mysqlbinlogmysql-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]:binlogfile![piece]:howmanypiecewillsplit,isaHighlybalancedhistogram,findwhichtimegeneratebiggestbinlog.(must:piece<2000000)[bigtrxsize](bytes):largerthanthissizetrxwillview.(must:trx>256(bytes))[bigtrxtime](sec):largerthanthissectrxwillview.(must:>0(sec))
使用方法
./infobinmysql-bin.0002742200000400>log1.log
mysql-bin.000274:binlog名字
2:分为多少piece来统计生成直方图
200000:事物大小 大于约200K的事物进行汇总
400:事物持续时间大于400秒的时间进行汇总
四、本工具的意义本工具主要的意义包含4个方面
能够更加清晰找到一个事物如下:
>GtidEvent:Pos:504(0X1f8)N_pos:569(0X239)Time:1496993578Event_size:65(bytes)Gtid:89dfa8a4-cb13-11e6-b54-0c29a879a3:2-->QueryEvent:Pos:569(0X239)N_Pos:641(0X281)Time:1496993578Event_size:72(bytes)Exe_time:0Use_db:testStatment(35b-trun):BEGIN/*!Trxbegin!*/Gno:2---->MapEvent:Pos641(0X281)N_pos:689(0X2b1)Time:1496993578Event_size:48(bytes)TABLE_ID:142DB_NAME:testTABLE_NAME:testGno:2------>InsertEvent:Pos:689(0X2b1)N_pos:733(0X2dd)Time:1496993578Event_size:44(bytes)Dmlontable:test.testtable_id:142Gno:2>XidEvent:Pos:733(0X2dd)N_Pos:764(0X2fc)Time:1496993578Event_size:31(bytes)COMMIT;/*!Trxend*/Gno:2
显然这是一个事物
能够通过直方图判断binlog什么时候生成量更大如下:
--Pieceview:(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有哪些大事物如下:
--Largethan700000(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中有哪些未及时提交的事物如下:
--Largethan400(secs)trx:(1)Trx_sec:406(sec)trx_begin_time:1502441602trx_end_time:1502442008trx_query_pos:592514409trx_xid_pos:592515464query_exe_time:90(2)Trx_sec:411(sec)trx_begin_time:1502441597trx_end_time:1502442008trx_query_pos:592518620trx_xid_pos:592519666query_exe_time:95(3)Trx_sec:407(sec)trx_begin_time:1502441601trx_end_time:1502442008trx_query_pos:592528469trx_xid_pos:592529524query_exe_time:91(4)Trx_sec:538(sec)trx_begin_time:1502441539trx_end_time:1502442077trx_query_pos:595102123trx_xid_pos:595103178query_exe_time:153(5)Trx_sec:531(sec)trx_begin_time:1502441547trx_end_time:1502442078trx_query_pos:595141415trx_xid_pos:595142470query_exe_time:145(6)Trx_sec:443(sec)trx_begin_time:1502441694trx_end_time:1502442137trx_query_pos:597451804trx_xid_pos:597452859query_exe_time:0(7)Trx_sec:546(sec)trx_begin_time:1502441592trx_end_time:1502442138trx_query_pos:597531453trx_xid_pos:597532508query_exe_time:100(8)Trx_sec:468(sec)trx_begin_time:1502441697trx_end_time:1502442165trx_query_pos:598471241trx_xid_pos:598472296query_exe_time:0(9)Trx_sec:515(sec)trx_begin_time:1502441693trx_end_time:1502442208trx_query_pos:600613882trx_xid_pos:600614928query_exe_time:0
这也是本次新加入的功能。也是为查看长期不提交事物定做的。
五、对长期未提交事物的测试比如我做如下一个事物:
flushbinarylogs;begin;insertintotestgpvalues(10);insertintotestgpvalues(20);selectsleep(5)fromtestgplimit2;commit;flushbinarylogs;
输出如下：
-------------Nowbegin--------------CheckMysqlVersionis:5.7.13-logCheckMysqlbinlogformatveris:V4CheckThisbinlogisclosed!CheckThisbinlogtotalsize:585(bytes)Note:loaddatainfilenotcheck!------------Detailnow-------------->FormatdescriptionlogEvent:Pos:4(0X4)N_pos:123(0X7b)Time:1502678321Event_size:119(bytes)>PreviousgtidEvent:Pos:123(0X7b)N_pos:194(0Xc2)Time:1502678321Event_size:71(bytes)>GtidEvent:Pos:194(0Xc2)N_pos:259(0X103)Time:1502678332Event_size:65(bytes)Gtid:4a6f2a67-5d87-11e6-a6bd-0c29a879a3:196824last_committed=0sequence_number=1-->QueryEvent:Pos:259(0X103)N_Pos:331(0X14b)Time:1502678322Event_size:72(bytes)Exe_time:0Use_db:testStatment(35b-trun):BEGIN/*!Trxbegin!*/Gno:196824---->MapEvent:Pos331(0X14b)N_pos:380(0X17c)Time:1502678322Event_size:49(bytes)TABLE_ID:294DB_NAME:testTABLE_NAME:testgpGno:196824------>InsertEvent:Pos:380(0X17c)N_pos:420(0X1a4)Time:1502678322Event_size:40(bytes)Dmlontable:test.testgptable_id:294Gno:196824---->MapEvent:Pos420(0X1a4)N_pos:469(0X1d5)Time:1502678322Event_size:49(bytes)TABLE_ID:294DB_NAME:testTABLE_NAME:testgpGno:196824------>InsertEvent:Pos:469(0X1d5)N_pos:509(0X1fd)Time:1502678322Event_size:40(bytes)Dmlontable:test.testgptable_id:294Gno:196824>XidEvent:Pos:509(0X1fd)N_Pos:540(0X21c)Time:1502678332Event_size:31(bytes)COMMIT;/*!Trxend*/Gno:196824>RotatelogEvent:Pos:540(0X21c)N_pos:585(0X249)Time:1502678332Event_size:45(bytes)-------------Totalnow--------------Trxtotal[counts]:1Eventtotal[counts]:10Maxtrxeventsize:119(bytes)Pos:4[0X4]Avgbinlogsize(/sec):53.182(bytes)[0.052(kb)]Avgbinlogsize(/min):3190.909(bytes)[3.116(kb)]--Pieceview:(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)]--Largethan200000(bytes)trx:Notrxfind!--Largethan8(secs)trx:(1)Trx_sec:10(sec)trx_begin_time:1502678322trx_end_time:1502678332trx_query_pos:259trx_xid_pos:540query_exe_time:0
这里我们看到了我们刚才做的没有及时提交的事物
--Largethan8(secs)trx:(1)Trx_sec:10(sec)trx_begin_time:1502678322trx_end_time:1502678332trx_query_pos:259trx_xid_pos:540query_exe_time:0
起始和结束位置有了直接mysqlbinlog查吧！