Shulou(Shulou.com)05/31 Report--

This article mainly introduces how to easily find things that are not submitted in time through binlog. The article is very detailed and has a certain reference value. Interested friends must read it!

I. Preface

I have written a help like this before:

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

But it does not include the latest query for things that have not been submitted for a long time, because this is my new addition, and this feature will be described in this article.

In addition, here are two more important binlog event and another two more important binlog event and query event and xid event, refer to the early articles.

Parsing MYSQL BINLOG binary format (3)-- QUERY_EVENT

Http://blog.itpub.net/7728585/viewspace-2133321/

Parsing MYSQL BINLOG binary format (7)-- Xid_log_event/XID_EVENT http://blog.itpub.net/7728585/viewspace-2133502/

Of course, this is a series. If you are interested, you can take a look at it all.

Http://blog.itpub.net/7728585/viewspace-2133188/ parsing MYSQL BINLOG binary format (1)-- preparing work http://blog.itpub.net/7728585/viewspace-2133189/ parsing MYSQL BINLOG binary format (2)-- FORMAT_DESCRIPTION_EVENT http://blog.itpub.net/7728585/viewspace-2133321/ parsing MYSQL BINLOG binary format (3)-- QUERY_EVENT http://blog.itpub.net/7728585/viewspace-2133429 / parsing MYSQL BINLOG binary format (4)-- TABLE_MAP_EVENT http://blog.itpub.net/7728585/viewspace-2133463/ parsing MYSQL BINLOG binary format (5)-- WRITE_ROW_EVENT http://blog.itpub.net/7728585/viewspace-2133469/ parsing MYSQL BINLOG binary format (6)-- UPDATE_ROW_EVENT/DELETE_ROW_EVENT http://blog.itpub.net/7728585/viewspace-2133502/ parsing MYSQL BINLOG Binary format (7)-- Xid_log_event/XID_EVENT http://blog.itpub.net/7728585/viewspace-2133506/ parsing MYSQL BINLOG binary format (8)-- GTID_LOG_EVENT/ANONYMOUS_GTID_LOG_EVENT and other http://blog.itpub.net/7728585/viewspace-2133534/ parsing MYSQL BINLOG binary formats (9)-- infobin parsing binlog help document http://blog.itpub.net/7728585/viewspace-2133537 / parsing MYSQL BINLOG binary format (10)-- question and answer II. Thinking of tool design

In innodb, if we show to open and submit a thing as follows:

Begin

Insert XXX

Update XXX

Select XXX

Commit

This is something we are familiar with, in MYSQL BINLOG line format (of course, this tool can also be used in statement format binlog)

The whole thing contains the following event

GTID EVENT

-- QUERY EVENT

-MAP EVENT

-WRITE EVENT (insert)

-MAP EVENT

-UPDATE_ROW_EVENT (update)

-(select has no binlog generated)

XID EVENT (commit)

There is a 4-byte time in the header in each event, which is the time of the new era.

And this time comes from a set_time () in the setting thread at the beginning of the dispatch_command function.

Function

Start_utime= utime_after_lock= my_micro_time ()

This time is recorded in XID EVENT when the commit command is initiated. So we got a design idea.

We can use the time of XID EVENT-the time of QUERY EVENT to get a time difference as the duration of things.

But it is important to note that if it is not submitted manually but automatically, of course, there is no thing that is not submitted in time.

And the use of QUERY EVENT instead of GTID EVENT here is to be compatible with cases where GTID is not enabled.

In 5. 7, there will be anonymous GTID EVENT even if GTID is not enabled.

It is also worth noting that even if a thing lasts for a long time, it may not be submitted in time.

Things include select statements that do not record binlog, which cannot be determined by binlog, but

We can at least find the DML statement in this long-uncommitted thing and give it to the developer to analyze what it is.

Reason.

III. Tool description

This tool actually comes from the tool infobin, which I wrote when I was learning binlog event earlier, this time because it appeared online.

A large number of things that were not submitted in time, thus adding new features.

The help documentation for this tool is available at

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

To put it simply, this tool is divided into two parts, called DETAIL and TOTAL

The first part

Analyze the native MYSQL BINLOG one by one (commonly used EVENT for analysis), this part

Called the DETAIL part.

Part II

The TOTAL part is obtained by scanning the data and summarizing the input information of the user. The following information will be counted in TOTAL.

Trx total [counts]: the total number of things

Event total [counts]: total number of event

Avg binlog size (/ sec): average size of binlog generated per second

Avg binlog size (/ min): average size of binlog generated per minute

-- Piece view:

A highly balanced histogram is obtained according to the user-specified piece size, which is used to find out whether there is a certain period of time when the binlog is particularly large.

-Large than xxx (bytes) trx:

For things larger than xxx BYTES, there will be a summary at the end, which gives the starting position of the big thing, the location of the end of the trx_begin_p, the location of the end trx_end_p.

-Large than xxx (secs) trx:

Things larger than xxx seconds will be summarized, giving the start time trx_begin_time, end time trx_end_time, start position trx_query_pos

End position trx_xid_pos, this function is my new addition.

With the beginning and end of binlog, it is very convenient to find out what the DML statement is.

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

Use help

[dbadmin@bak ~] $. / infobin [Author]: gaopeng [QQ]: 22389860 [blog]: http://blog.itpub.net/7728585/-- USAGE:./infobin [binlogfile] [piece] [bigtrxsize] [binlogfile]: binlogfile! [piece]: how many piece will split,is a Highly balanced histogram, find which time generate biggest binlog. (must:piece256 (bytes)) [bigtrxtime] (sec): larger than this sec trx will view. (must: > 0 (sec))

Usage

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

Mysql-bin.000274:binlog name

2: how many piece are divided into to generate histogram

200000: summarize things whose size is larger than about 200K

400: summarize the time when the duration of things is greater than 400 seconds

IV. The significance of this tool

The main meaning of this tool includes four aspects.

Can find one thing more clearly as follows:

> Gtid Event:Pos:504 (0X1f8) N_pos:569 (0X239) Time:1496993578 Event_size:65 (bytes) Gtid:89dfa8a4-cb13-11e6-b54-0c29a879a3VR 2muri-> 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 beginnings / 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

Obviously, this is one thing.

The histogram can be used to determine when the binlog will generate more quantity as follows:

-- Piece view: (1) Time:1487560299-1487560543 (244s) piece:107374204 (bytes) [104857.625 (kb)] (2) Time:1487560543-1487560751 (208s) piece:107374204 (bytes) [104857.625 (kb)] (3) Time:1487560751-1487561012 (261s) piece:107374204 (bytes) [104857.625 (kb)] (4) Time:1487561012-1487561480468 (s) piece:107374204 (bytes) [104857.625 (kb)] (5) Time:1487561480-1487562682 (1202 (s)) piece:107374204 (bytes) [104857.625 (kb)] (6) Time:1487562682-1487563492 (810s) 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 S)) piece:107374204 (bytes) [104857.625 (kb)] (10) Time:1487564159-1487564409 (250s) piece:107374204 (bytes) [104857.625 (kb)]

It is clear at a glance that the binlog generated by 1487560543-1487560751 and 1487564159-1487564409 is larger (note that it is the time of the new era)

It can be more clear that there are some big things in binlog as follows:

-- 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: 3182648 [0X12F84D78]

The significance of big things is self-evident, because the three queues in the order_commit function, FLUSH queue, SYNC queue and COMMIT queue, are all serial.

Too many things will block the submission of other things in the whole library (GROUP COMMIT)

You can see more clearly what was not submitted in time in this binlog as follows:

-- 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

This is also a new feature added this time. It is also customized to view things that have not been submitted for a long time.

5. Testing of things that have not been submitted for a long time

For example, I do the following thing:

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

The output is as follows:

-Now begin-Check Mysql Version is:5.7.13-logCheck Mysql binlog format ver is:V4Check This binlog is closeness check This binlog total size:585 (bytes) Note:load data infile not checkpoint house 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 beginnings / 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]: 1Event total [counts]: 10Max 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 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 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

Here we see what we just did and didn't submit in time.

-- 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

Start and end positions have a direct mysqlbinlog check it!

The above is all the contents of the article "how to easily find things that were not submitted in time through binlog". Thank you for reading! Hope to share the content to help you, more related knowledge, welcome to follow the industry information channel!

Welcome to subscribe "Shulou Technology Information " to get latest news, interesting things and hot topics in the IT industry, and controls the hottest and latest Internet news, technology news and IT industry trends.