如何通过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，参考的早期的文章

当然这是一个系列如果有兴趣可以全部看看

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，这次由于线上出现了
大量未及时提交的事物，从而加入了新的功能。
本工具的帮助文档在

简单的说本工具总共分为两部分，分别叫做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支持不好。

作者微信:

时间： 2024-07-31 23:13:12

如何通过binlog 轻松的找到没有及时提交的事物(infobin工具)的相关文章

如何快速找到MYSQL binlog中的大事物以及生成量分布(infobin工具)

原创注明出处: 1.问题引出: 某些时候需要判断binlog中是否有大事物的存在,比如在解决master-slave延迟 高的情况下.一般我们使用mysqlbinlog来找,但是遇到一个问题,使用mysqbinlog 来找比较麻烦,有没有一个快速的方法呢?当然使用shell脚本来做一些格式化,也 可以找到,这里介绍一个工具叫做infobin 来做,是我自己编写的用C语言完成 2.infobin能做什么? --找到你大于你指定大小日志量的事物,一般定义为大事物,给出了其位置,通过位置就能在mysq

Visual Studio 2013引入联网IDE体验 自动同步设备

近日,Visual Studio 2013以 Visual Studio 2012 和后续的 Visual Studio 更新中的进展为基础构建而成,为开发团队提供需要的解决方案,使其接纳这种转变并开发和交付利用下一波 Windows 平台创新 (Windows 8.1) 的新式应用程序,同时在所有 Microsoft 平台上支持多种设备和服务.设备和服务体验有了根本性的变革,改变了行业对软件开发的处理方式.消费者.客户和员工现在需要一种全新的应用程序.他们要求应用程序在多种屏幕和设备上提供最佳

新一代物联网助力智慧城市 手机App可轻松找到空车位

新一代物联网技术还有更多的应用,我们到南京江北新区的新一代物联网技术商用实验区去看一看.     手机App轻松找到空车位 如今开车上下班的上班族经常会为了找停车位发愁,而在江北新区,一些上班族通过手机App就可以轻松地找到空车位.     新一代物联网中心技术人员 周建明 新一代物联网中心技术人员周建明介绍,每个车位上面安装了这样一个智慧停车检测器,车位的信息进行实时的采集,有车辆来了之后,检测器就会检测到有车,把信息发送到后台.车辆走了之后,也会发送一个数据到后台,说这辆车走了,该收费了.

MySQL运维案例分析：Binlog中的时间戳

背景 众所周知,在Binlog文件中,经常会看到关于事件的时间属性,出现的方式都是如下这样的. #161213 10:11:35 server id 11766 end_log_pos 263690453 CRC32 0xbee3aaf5 Xid = 83631678 我们清楚地知道,161213 10:11:35表示的就是时间值,但除此之外呢?还能知道它的什么信息呢? 案例分析 先从一个典型的案例入手来讲述其中的细节,比如曾经在Galera Cluster碰到的一个问题,可以先看一段Binlo

谷歌站长指南：更轻松地恢复被黑客入侵的网站

原文:Easier recovery for hacked sites http://googlewebmaster-cn.blogspot.***/2013/11/blog-post.html 发布者:Meenali Rungta,反网络垃圾小组;Hadas Fester,网站站长工具小组   众所周知,作为网站所有者,如果发现自己的网站遭到黑客入侵或恶意软件入侵,必定会感到万分焦虑,而要在短时间内清除这些恶意内容却绝非易事.为了解决这个难题,我们一直致力于简化网站恢复的操作和恶意内容的清除流

Eclipse V3.2 Callisto热点：比以往任何时候都轻松地开始使用Eclipse

Callisto 是什么? Callisto 是针对 Eclipse 的 10 个项目的协同发布,它大大简化了准备和运行 Eclipse 的过程,使您可以随意做自己想做的事.Callisto 并不是 Eclipse V3.2 的另外一种定制版本,也不是访问 Eclipse Callisto Discovery Site 时看到的那些项目的替代产品.使用 Callisto Discovery Site,可以轻松获得您在进行 Web 或 Java 2 Platform, Enterprise Edi

Sophos UTM轻松搭建VPN网络

伴随企业和公司的不断扩张,员工出差日趋频繁,驻外机构及客户群分布日益分散,合作伙伴日益增多,越来越多的现代企业迫切需要利用公共Internet资源来进行促销.销售.售后服务.培训.合作及其它咨询活动,这为VPN的应用奠定了广阔市场. VPN(Virtual http://www.aliyun.com/zixun/aggregation/33969.html">Private Network,虚拟私有网)是近年来随着Internet的广泛应用而迅速发展起来的一种新技术,实现在公用网络上构建私

使用Sophos UTM轻松搭建VPN网络

伴随企业和公司的不断扩张,员工出差日趋频繁,驻外机构及客户群分布日益分散,合作伙伴日益增多,越来越多的现代企业迫切需要利用公共Internet资源来进行促销.销售.售后服务.培训.合作及其它咨询活动,这为VPN的应用奠定了广阔市场. VPN(Virtual http://www.aliyun.com/zixun/aggregation/33969.html">Private Network,虚拟私有网)是近年来随着Internet的广泛应用而迅速发展起来的一种新技术,实现在公用网络上构建私

新手教程——在Linux Mint 16中找到保存的WiFi密码

当你使用 WEP,WPA 或 WPA2-PSK 连接到无线网络时,选择"自动连接"后密码将保存在Linux Mint(或任何其他的操作系统)中.试想一个情况,例如你需要提供密码给来访者,这时你需要知道WiFi密码,然而你有没有把它记下来.你可以轻松地找到之前连接的WiFi密码. 在这篇新手教程中,我们将会指导你如何在 Linux Mint 16 中找到保存的 WiFi 密码. 在 Linux Mint 中找到保存的 WiFi 密码: 找到保存的 WiFi 密码,其实过程非常简单.点击