mysql binlog rotate_binlog rotate分析.md

最新推荐文章于 2024-05-09 09:21:44 发布
最新推荐文章于 2024-05-09 09:21:44 发布
阅读量352 收藏
点赞数
文章标签： mysql binlog rotate
版权声明：本文为博主原创文章，遵循 CC 4.0 BY-SA 版权协议，转载请附上原文出处链接和本声明。
本文链接：https://blog.csdn.net/weixin_34278412/article/details/113906013
版权

现在线上MySQL(官方版本 5.6.34)碰到一个现象：

### 环境配置：

- 1、binlog_size=1g

- 2、binlog_format=row

- 3、mysql开了双一

- 4、 没开gtid

### 现象描述：

- 1、某个binlog实际大小8g+，解析binlog后发现最后一个事务是小事务，往前推200多个事务才是大事务(update 700w的数据)。

- 2、大事务与200多个小事务都是不同的db

> 猜测

- 1、怀疑是组提交的原因，但是发现binlog 写入时间戳并不一样，大事务的binlog时间戳与该binlog文件的最后一个事务的时间戳相差30多秒。

- 2、这个rotate前，应该是要等引擎层提交完，如果在这个中间有新的事务进来，应该不能立即rotate，对于这个猜测没法确认，也没法否认。

> 疑问

- 感觉这个现象不太正常，按照以往的认知，binlog在完成一个事务以后，如果binlog文件大小达到设置的最大阈值以后，就会跳转到下一个文件，但是现在好像与之相悖，不解其中原因。

### 分析binlog：

#### 定位大事务的位置

```

mysqlbinlog -vv mysqlbinlog_file > mysqlbinlog_res.log

grep -n -B 1 "COMMIT" mysqlbinlog_res.log > file.log

```

```

less file.log

42614655-#190729 13:08:34 server id 10169 end_log_pos 470106563 CRC32 0x25e88a38 Xid = 4104520291

42614656:COMMIT/*!*/;

--

42614695-#190729 13:08:34 server id 10169 end_log_pos 470107657 CRC32 0xd9a65220 Xid = 4104520297

42614696:COMMIT/*!*/;

--

42614751-#190729 13:08:34 server id 10169 end_log_pos 470108164 CRC32 0x99e50c49 Xid = 4104520330

42614752:COMMIT/*!*/;

--

392578996-#190729 12:54:12 server id 10169 end_log_pos 2915555141 CRC32 0x36771ac4 Xid = 4103492840

392578997:COMMIT/*!*/;

--

392579051-#190729 13:08:34 server id 10169 end_log_pos 2915555690 CRC32 0x423b0ed1 Xid = 4104520361

392579052:COMMIT/*!*/;

--

392579088-#190729 13:08:34 server id 10169 end_log_pos 2915556571 CRC32 0xc8616191 Xid = 4104520410

392579089:COMMIT/*!*/;

省略部分信息

392588781-#190729 13:08:43 server id 10169 end_log_pos 2915736247 CRC32 0x780e8edf Xid = 4104544570

392588782:COMMIT/*!*/;

--

392588808-#190729 13:08:43 server id 10169 end_log_pos 2915736552 CRC32 0xdec22128 Xid = 4104544573

392588809:COMMIT/*!*/;

--

392588880-#190729 13:08:43 server id 10169 end_log_pos 2915737160 CRC32 0xa5e09a6b Xid = 4104544585

392588881:COMMIT/*!*/;

--

392588908-#190729 13:08:43 server id 10169 end_log_pos 2915737527 CRC32 0x045cf145 Xid = 4104544639

392588909:COMMIT/*!*/;

--

392588936-#190729 13:08:43 server id 10169 end_log_pos 2915737898 CRC32 0xaeeb7e1d Xid = 4104544711

392588937:COMMIT/*!*/;

--

392589114-#190729 13:08:43 server id 10169 end_log_pos 2915739511 CRC32 0xfbf4d527 Xid = 4104544377

392589115:COMMIT/*!*/;

--

392589170-#190729 13:08:43 server id 10169 end_log_pos 2915740025 CRC32 0x8798dc5c Xid = 4104544691

392589171:COMMIT/*!*/;

--

392589197-#190729 13:08:43 server id 10169 end_log_pos 2915740337 CRC32 0xd509f01b Xid = 4104544654

392589198:COMMIT/*!*/;

(END)

```

#### 分析得到的信息

- 1、通过结果可以看到大事务提交完成是binlog文件的行号是392578997，往前推一个事务，提交完成后的行号是42614752，期间相差3.2亿行，就是说这个事务总共写了3.2亿行的binlog，大事务提交的时间是12:54:12，Xid = 4103492840，结束的pos值是2915555141

- 2、最后一个事务的提交时间13:08:43，Xid = 4104544654，结束的pos值是2915740337

#### 并得出如下推测

- 1、那个超大事务(简称BT)实际启动时间是很早前的，log里看到的12:54:12是它发起事务的时间。

- 2、binlog里看到BT也是在12:54:12发起commit，但实际commit完成时间大概是在13:08:43(这个时间完全写完binlog)，因此binlog能看到大量12:54:12只有的新event继续写入，这点从他xid=4103492840 也能看出来，他的前一个xid是(远远小于这个xid)

```

42614751-#190729 13:08:34 server id 10169 end_log_pos 470108164 CRC32 0x99e50c49 Xid = 4104520330

40449131:COMMIT/*!*/;

```

- 3、可以从第 42614751 行这里，end_log_pos 470108164看，从这行开始，后面一堆的 end_log_pos 4701****，能看出是被堆积了的event。

```

sed -n '42614752,392578997p' mysqlbinlog_res.log > tmp.log

```

```

less tmp.log

#190729 12:54:12 server id 10169 end_log_pos 470108386 CRC32 0x0aceb552 Table_map: `yymarket`.`t_auto_marketing_short_message` mapped to number 1997

# at 470108386

#190729 12:54:12 server id 10169 end_log_pos 470116549 CRC32 0xa2e2c629 Update_rows: table id 1997

# at 470116549

#190729 12:54:12 server id 10169 end_log_pos 470124622 CRC32 0x1a7cef66 Update_rows: table id 1997

# at 470124622

#190729 12:54:12 server id 10169 end_log_pos 470132606 CRC32 0x33b45a96 Update_rows: table id 1997

# at 470132606

#190729 12:54:12 server id 10169 end_log_pos 470140590 CRC32 0x7405180d Update_rows: table id 1997

# at 470140590

#190729 12:54:12 server id 10169 end_log_pos 470148506 CRC32 0x8255a16f Update_rows: table id 1997

# at 470148506

#190729 12:54:12 server id 10169 end_log_pos 470156464 CRC32 0x485fdd62 Update_rows: table id 1997

# at 470156464

#190729 12:54:12 server id 10169 end_log_pos 470164404 CRC32 0xa2981b74 Update_rows: table id 1997

# at 470164404

#190729 12:54:12 server id 10169 end_log_pos 470172308 CRC32 0x5fae703f Update_rows: table id 1997

# at 470172308

#190729 12:54:12 server id 10169 end_log_pos 470180254 CRC32 0xcff343ee Update_rows: table id 1997

# at 470180254

#190729 12:54:12 server id 10169 end_log_pos 470188200 CRC32 0x76cf3055 Update_rows: table id 1997

# at 470188200

#190729 12:54:12 server id 10169 end_log_pos 470196110 CRC32 0xcbecb2ca Update_rows: table id 1997

# at 470196110

#190729 12:54:12 server id 10169 end_log_pos 470204038 CRC32 0xe20c795f Update_rows: table id 1997

…………

```

> 注

- 1、将所有BEGIN打头的行号打印出来

- 2、将后一个行号减去前一个行号，可定位到大事务。

#### binlog最后一批事务

```

392588781-#190729 13:08:43 server id 10169 end_log_pos 2915736247 CRC32 0x780e8edf Xid = 4104544570

392588782:COMMIT/*!*/;

--

392588808-#190729 13:08:43 server id 10169 end_log_pos 2915736552 CRC32 0xdec22128 Xid = 4104544573

392588809:COMMIT/*!*/;

--

392588880-#190729 13:08:43 server id 10169 end_log_pos 2915737160 CRC32 0xa5e09a6b Xid = 4104544585

392588881:COMMIT/*!*/;

--

392588908-#190729 13:08:43 server id 10169 end_log_pos 2915737527 CRC32 0x045cf145 Xid = 4104544639

392588909:COMMIT/*!*/;

--

392588936-#190729 13:08:43 server id 10169 end_log_pos 2915737898 CRC32 0xaeeb7e1d Xid = 4104544711

392588937:COMMIT/*!*/;

--

392589114-#190729 13:08:43 server id 10169 end_log_pos 2915739511 CRC32 0xfbf4d527 Xid = 4104544377

392589115:COMMIT/*!*/;

--

392589170-#190729 13:08:43 server id 10169 end_log_pos 2915740025 CRC32 0x8798dc5c Xid = 4104544691

392589171:COMMIT/*!*/;

--

392589197-#190729 13:08:43 server id 10169 end_log_pos 2915740337 CRC32 0xd509f01b Xid = 4104544654

392589198:COMMIT/*!*/;

```

### 二阶段提交分析

![本地图片](img/binlog.png)

- 1、redo prepare --> 这个时候是redo的组提交，即flush队列，会标记是否rotate binlog。

- 2、binlog commit --> 这个时候是binlog的组提交，即sync队列。

- 3、redo commit --> 这个时候是commit队列，会具体决定是否rotate binlog。

#### 由此得出

- 1、binlog 切换是在 flush 队列刷盘完成后，进行切换标记的设置

- 2、binlog 切换是在 commit 队列引擎层提交后完成实际的切换

- 3、大事务提交最慢的是sync阶段，在sync阶段完成之前，其他后提交的事务是可以进行提交的，且可以进入flush 阶段进行binlog的flush，也就是写入到binlog，因此这种现象出现了。

### 模拟测试

#### 1、环境准备

(1)准备8张测试表，t1-7

```

CREATE TABLE t1 (id int(11) NOT NULL AUTO_INCREMENT primary key ,name char(50) DEFAULT NULL,name2 char(10) DEFAULT NULL);

create table t2 like t1;

create table t3 like t1;

create table t4 like t1;

create table t5 like t1;

create table t6 like t1;

create table t7 like t1;

```

(2)给t1表准备500w行数据

```

https://gitee.com/mo-shan/prepare_test_data_for_mysql.git

cd prepare_test_data_for_mysql

```

```

vim conf/mysql.xml #根据实际情况编辑连接信息

test

test

3311

172.28.84.239

```

```

bash start.sh

+++++++++++++++++++++++++++++++++++++++++++++++

本次连接验证成功，连接信息如下

+++++++++++++++++++++++++++++++++++++++++++++++

用户名：test

密 码：test

端 口：3311

主 机：172.28.84.239

+++++++++++++++++++++++++++++++++++++++++++++++

请注意:

该程序仅支持整型、字符型及时间类型的字段，

如存在其他类型将可能导致未知的错误！！！

请联系QQ：907771586

----------------------------------

0.结束运行。

1.自动获取字段及各字段长度。

2.手动输入字段及各字段长度。

3.准备sysbench测试数据。

4.更改连接信息。

5.编辑配置文件。

----------------------------------

请输入您的选择:

```

> 可以选择5编辑配置文件

```

注：该行是提示信息，不会保存至配置文件，不用理会直接修改配置文件即可。 的说明-->

1

1

1

5000000

11

50

test:test:3311:172.28.84.239

```

> 按照提示更新，其实只需要更新row标签的配置，即改成需要准备的数据行数，这里是5000000

```

+++++++++++++++++++++++++++++++++++++++++++++++

本次连接验证成功，连接信息如下

+++++++++++++++++++++++++++++++++++++++++++++++

用户名：test

密 码：test

端 口：3311

主 机：172.28.84.239

+++++++++++++++++++++++++++++++++++++++++++++++

请注意:

该程序仅支持整型、字符型及时间类型的字段，

如存在其他类型将可能导致未知的错误！！！

请联系QQ：907771586

----------------------------------

0.结束运行。

1.自动获取字段及各字段长度。

2.手动输入字段及各字段长度。

3.准备sysbench测试数据。

4.更改连接信息。

5.编辑配置文件。

----------------------------------

请输入您的选择: 1

----------------------

服务器现有的数据库

----------------------

1.test

----------------------

输入r返回上一层菜单，请输入库名: 1

----------------------

test库现有的表

----------------------

1.t1

2.t2

3.t3

4.t4

5.t5

6.t6

7.t7

----------------------

输入r返回上一层菜单，请输入表名: 1

----------------------------------

温馨提示

----------------------------------

当数据量较大，受网络或机器本身影

响较大，可能会导致load失败，

此时程序将会分小块load到各个分片。

默认阀值是1000w数据量，即当数据量

超过1000w时，程序自动将其分片！！！

----------------------------------

---------------------------------

第1个分片的连接信息是:

用户名：test

密 码：test

端口号：3311

主 机：172.28.84.239

第1个分片验证成功

---------------------------------

现在开始准备各分片的数据---

++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

开始准备第1个分片的数据:---------------------现在的时间：06:37:11 PM

当前准备数据的进程号为:5076

请耐心等待，现已用时:3s

第1个分片的数据准备完成----------------------现在的时间：06:37:15 PM

++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

现在开始load各分片的数据---

++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

开始load第1个分片----------------------------现在的时间：06:37:15 PM

当前load的进程号为:5199

请耐心等待，现已用时:36s

导入完成，下面开始验证数据量是否正确---------现在的时间：06:37:54 PM

验证结束-------------------------------------现在的时间：06:37:55 PM

第1个分片导入成功----------------------------现在的时间：06:37:55 PM

++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

请输入任意键返回主菜单，或输入q退出程序:

…………

mysql(test@localhost mysqld.sock)> use test

Reading table information for completion of table and column names

You can turn off this feature to get a quicker startup with -A

Database changed

mysql(test@localhost mysqld.sock)> select count(*) from t1;

+----------+

| count(*) |

+----------+

| 5000000 |

+----------+

1 row in set (0.77 sec)

mysql(test@localhost mysqld.sock)>

```

(3)给其他表准备insert语句

```

#!/bin/bash

# File Name : /tmp/prepare.sh

# Author : moshan

# Mail : mo_shan@yeah.net

# Created Time: 2019-07-30 18:42:08

# Function :

#########################################################################

for table in 2 3 4 5 6 7

do

{

for ((i=1;i<=500000;i++))

do

echo ${i}

done|awk -v table="${table}" -v time="$(date +%s)" '{print "insert into t"table"(name,name2) select "$0","time";"}' > /tmp/file_${table}.log

} &

done

wait

```

```

bash /tmp/prepare.sh

```

(4)给其他表准备写入脚本

```

#!/bin/bash

# File Name : /tmp/insert.sh

# Author : moshan

# Mail : mo_shan@yeah.net

# Created Time: 2019-07-30 18:42:08

# Function :

#########################################################################

pid=""

for table in 2 3 4 5 6 7

do

cat /tmp/file_${table}.log|mysql test &

pid="${pid} $!"

done

echo "kill -9 ${pid}"

```

(5)测试

- 开一个mysql会话

> 模拟一个大事务提交，这一步应该需要一些时间，然后可以紧接着做下一步。

```

mysql(test@localhost mysqld.sock)> flush logs;begin;select now();update t1 set name2="loiugbxaad";

Query OK, 0 rows affected (0.01 sec)

Query OK, 0 rows affected (0.00 sec)

+---------------------+

| now() |

+---------------------+

| 2019-07-31 10:50:00 |

+---------------------+

1 row in set (0.00 sec)

```

- 开一个系统shell

> 不断的往库里写数据，模拟大事务提交过程中有其他小事务写入。

```

moshan /tmp > bash /tmp/insert.sh

```

```

mysql(test@localhost mysqld.sock)> flush logs;begin;select now();update t1 set name2="loiugbxaad";

Query OK, 0 rows affected (0.01 sec)

Query OK, 0 rows affected (0.00 sec)

+---------------------+

| now() |

+---------------------+

| 2019-07-31 10:50:00 |

+---------------------+

1 row in set (0.00 sec)

Query OK, 5000000 rows affected (22.32 sec)

Rows matched: 5000000 Changed: 5000000 Warnings: 0

mysql(test@localhost mysqld.sock)> select now();commit;

+---------------------+

| now() |

+---------------------+

| 2019-07-31 10:50:40 |

+---------------------+

1 row in set (0.00 sec)

Query OK, 0 rows affected (3.88 sec)

mysql(test@localhost mysqld.sock)>

```

(6)分析binlog

```

BEGIN

/*!*/;

# at 1397

#190731 10:50:07 server id 551953311 end_log_pos 1467 CRC32 0x91f81572 Rows_query

# insert into t2(name,name2) select 1,1564539982

# at 1467

#190731 10:50:07 server id 551953311 end_log_pos 1518 CRC32 0x008b4250 Table_map: `test`.`t2` mapped to number 108

# at 1518

#190731 10:50:07 server id 551953311 end_log_pos 1571 CRC32 0x84c21a57 Write_rows: table id 108 flags: STMT_END_F

BINLOG '

3wFBXR2fI+YgRgAAALsFAACAAC5pbnNlcnQgaW50byB0MihuYW1lLG5hbWUyKSBzZWxlY3QgMSwx

NTY0NTM5OTgychX4kQ==

3wFBXROfI+YgMwAAAO4FAAAAAGwAAAAAAAEABHRlc3QAAnQyAAMD/v4E/pb+HgZQQosA

3wFBXR6fI+YgNQAAACMGAAAAAGwAAAAAAAEAAgAD//gBAAAAATEKMTU2NDUzOTk4MlcawoQ=

'/*!*/;

### INSERT INTO `test`.`t2`

### SET

### @1=1 /* INT meta=0 nullable=0 is_null=0 */

### @2='1' /* STRING(150) meta=65174 nullable=1 is_null=0 */

### @3='1564539982' /* STRING(30) meta=65054 nullable=1 is_null=0 */

# at 1571

#190731 10:50:07 server id 551953311 end_log_pos 1602 CRC32 0x6f81deb9 Xid = 75

COMMIT/*!*/;

…………省略部分

BEGIN

/*!*/;

# at 11365643

#190731 10:50:00 server id 551953311 end_log_pos 11365699 CRC32 0x8429466e Rows_query

# update t1 set name2="loiugbxaad"

# at 11365699

#190731 10:50:00 server id 551953311 end_log_pos 11365750 CRC32 0xea173242 Table_map: `test`.`t1` mapped to number 115

# at 11365750

#190731 10:50:00 server id 551953311 end_log_pos 11373960 CRC32 0x8eec7425 Update_rows: table id 115

# at 11373960

#190731 10:50:00 server id 551953311 end_log_pos 11382170 CRC32 0xc7c22a0d Update_rows: table id 115

# at 11382170

#190731 10:50:00 server id 551953311 end_log_pos 11390380 CRC32 0x6381ad18 Update_rows: table id 115

# at 11390380

#190731 10:50:00 server id 551953311 end_log_pos 11398590 CRC32 0x9d9fdc2d Update_rows: table id 115

# at 11398590

#190731 10:50:00 server id 551953311 end_log_pos 11406800 CRC32 0x85890693 Update_rows: table id 115

# at 11406800

#190731 10:50:00 server id 551953311 end_log_pos 11415010 CRC32 0x36ccb4ea Update_rows: table id 115

# at 11415010

#190731 10:50:00 server id 551953311 end_log_pos 11423220 CRC32 0x92d91a03 Update_rows: table id 115

# at 11423220

…………省略部分

### UPDATE `test`.`t1`

### WHERE

### @1=1 /* INT meta=0 nullable=0 is_null=0 */

### @2='00227127129686380467069612305467831772932544113525' /* STRING(150) meta=65174 nullable=1 is_null=0 */

### @3='0004670696' /* STRING(30) meta=65054 nullable=1 is_null=0 */

### SET

### @1=1 /* INT meta=0 nullable=0 is_null=0 */

### @2='00227127129686380467069612305467831772932544113525' /* STRING(150) meta=65174 nullable=1 is_null=0 */

### @3='loiugbxaad' /* STRING(30) meta=65054 nullable=1 is_null=0 */

### UPDATE `test`.`t1`

### WHERE

### @1=2 /* INT meta=0 nullable=0 is_null=0 */

### @2='00726268377216911342271271296863804670696123054678' /* STRING(150) meta=65174 nullable=1 is_null=0 */

### @3='0068638046' /* STRING(30) meta=65054 nullable=1 is_null=0 */

### SET

### @1=2 /* INT meta=0 nullable=0 is_null=0 */

### @2='00726268377216911342271271296863804670696123054678' /* STRING(150) meta=65174 nullable=1 is_null=0 */

### @3='loiugbxaad' /* STRING(30) meta=65054 nullable=1 is_null=0 */

…………省略部分

### UPDATE `test`.`t1`

### WHERE

### @1=4999999 /* INT meta=0 nullable=0 is_null=0 */

### @2='00932544113525388347792009510108027638614199408395' /* STRING(150) meta=65174 nullable=1 is_null=0 */

### @3='0072932544' /* STRING(30) meta=65054 nullable=1 is_null=0 */

### SET

### @1=4999999 /* INT meta=0 nullable=0 is_null=0 */

### @2='00932544113525388347792009510108027638614199408395' /* STRING(150) meta=65174 nullable=1 is_null=0 */

### @3='loiugbxaad' /* STRING(30) meta=65054 nullable=1 is_null=0 */

### UPDATE `test`.`t1`

### WHERE

### @1=5000000 /* INT meta=0 nullable=0 is_null=0 */

### @2='00296863804670696123054678317729325441135253883477' /* STRING(150) meta=65174 nullable=1 is_null=0 */

### @3='0017729325' /* STRING(30) meta=65054 nullable=1 is_null=0 */

### SET

### @1=5000000 /* INT meta=0 nullable=0 is_null=0 */

### @2='00296863804670696123054678317729325441135253883477' /* STRING(150) meta=65174 nullable=1 is_null=0 */

### @3='loiugbxaad' /* STRING(30) meta=65054 nullable=1 is_null=0 */

# at 684316598

#190731 10:50:40 server id 551953311 end_log_pos 684316629 CRC32 0x3368df74 Xid = 68

COMMIT/*!*/;

# at 684316629

#190731 10:50:40 server id 551953311 end_log_pos 684316694 CRC32 0xd3549235 GTIDlast_committed=32692sequence_number=32699rbr_only=yes

/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;

SET @@SESSION.GTID_NEXT= '842db95c-453f-11e9-8d4f-94b86dd02e79:585204'/*!*/;

# at 684316694

#190731 10:50:40 server id 551953311 end_log_pos 684316766 CRC32 0xb5ae7dc3 Querythread_id=20exec_time=0error_code=0

SET TIMESTAMP=1564541440/*!*/;

BEGIN

/*!*/;

# at 684316766

#190731 10:50:40 server id 551953311 end_log_pos 684316839 CRC32 0xab54b9f9 Rows_query

# insert into t4(name,name2) select 5473,1564539982

# at 684316839

#190731 10:50:40 server id 551953311 end_log_pos 684316890 CRC32 0xd2dcf657 Table_map: `test`.`t4` mapped to number 111

# at 684316890

#190731 10:50:40 server id 551953311 end_log_pos 684316946 CRC32 0xa76270f8 Write_rows: table id 111 flags: STMT_END_F

BINLOG '

AAJBXR2fI+YgSQAAAKfYySiAADFpbnNlcnQgaW50byB0NChuYW1lLG5hbWUyKSBzZWxlY3QgNTQ3

MywxNTY0NTM5OTgy+blUqw==

AAJBXROfI+YgMwAAANrYySgAAG8AAAAAAAEABHRlc3QAAnQ0AAMD/v4E/pb+HgZX9tzS

AAJBXR6fI+YgOAAAABLZySgAAG8AAAAAAAEAAgAD//hhFQAABDU0NzMKMTU2NDUzOTk4MvhwYqc=

'/*!*/;

### INSERT INTO `test`.`t4`

### SET

### @1=5473 /* INT meta=0 nullable=0 is_null=0 */

### @2='5473' /* STRING(150) meta=65174 nullable=1 is_null=0 */

### @3='1564539982' /* STRING(30) meta=65054 nullable=1 is_null=0 */

# at 684316946

#190731 10:50:40 server id 551953311 end_log_pos 684316977 CRC32 0x3c221376 Xid = 32774

COMMIT/*!*/;

# at 684316977

#190731 10:50:40 server id 551953311 end_log_pos 684317042 CRC32 0x5d9570a3 GTIDlast_committed=32697sequence_number=32700rbr_only=yes

/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;

SET @@SESSION.GTID_NEXT= '842db95c-453f-11e9-8d4f-94b86dd02e79:585205'/*!*/;

# at 684317042

#190731 10:50:40 server id 551953311 end_log_pos 684317114 CRC32 0x95fdcbb9 Querythread_id=17exec_time=0error_code=0

SET TIMESTAMP=1564541440/*!*/;

BEGIN

/*!*/;

# at 684317114

#190731 10:50:40 server id 551953311 end_log_pos 684317187 CRC32 0x0df2b73e Rows_query

# insert into t5(name,name2) select 5454,1564539982

# at 684317187

#190731 10:50:40 server id 551953311 end_log_pos 684317238 CRC32 0x707a040f Table_map: `test`.`t5` mapped to number 112

# at 684317238

#190731 10:50:40 server id 551953311 end_log_pos 684317294 CRC32 0xcf514ecf Write_rows: table id 112 flags: STMT_END_F

BINLOG '

AAJBXR2fI+YgSQAAAAPaySiAADFpbnNlcnQgaW50byB0NShuYW1lLG5hbWUyKSBzZWxlY3QgNTQ1

NCwxNTY0NTM5OTgyPrfyDQ==

AAJBXROfI+YgMwAAADbaySgAAHAAAAAAAAEABHRlc3QAAnQ1AAMD/v4E/pb+HgYPBHpw

AAJBXR6fI+YgOAAAAG7aySgAAHAAAAAAAAEAAgAD//hOFQAABDU0NTQKMTU2NDUzOTk4Ms9OUc8=

'/*!*/;

### INSERT INTO `test`.`t5`

### SET

### @1=5454 /* INT meta=0 nullable=0 is_null=0 */

### @2='5454' /* STRING(150) meta=65174 nullable=1 is_null=0 */

### @3='1564539982' /* STRING(30) meta=65054 nullable=1 is_null=0 */

# at 684317294

#190731 10:50:40 server id 551953311 end_log_pos 684317325 CRC32 0x4f12455d Xid = 32775

COMMIT/*!*/;

# at 684317325

#190731 10:50:40 server id 551953311 end_log_pos 684317390 CRC32 0xb0614d44 GTIDlast_committed=32697sequence_number=32701rbr_only=yes

/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;

SET @@SESSION.GTID_NEXT= '842db95c-453f-11e9-8d4f-94b86dd02e79:585206'/*!*/;

# at 684317390

#190731 10:50:40 server id 551953311 end_log_pos 684317462 CRC32 0x8b97316e Querythread_id=19exec_time=0error_code=0

SET TIMESTAMP=1564541440/*!*/;

BEGIN

/*!*/;

# at 684317462

#190731 10:50:40 server id 551953311 end_log_pos 684317535 CRC32 0xd69eda44 Rows_query

# insert into t7(name,name2) select 5451,1564539982

# at 684317535

#190731 10:50:40 server id 551953311 end_log_pos 684317586 CRC32 0x867c4c9e Table_map: `test`.`t7` mapped to number 114

# at 684317586

#190731 10:50:40 server id 551953311 end_log_pos 684317642 CRC32 0x5ce93dfc Write_rows: table id 114 flags: STMT_END_F

BINLOG '

AAJBXR2fI+YgSQAAAF/bySiAADFpbnNlcnQgaW50byB0NyhuYW1lLG5hbWUyKSBzZWxlY3QgNTQ1

MSwxNTY0NTM5OTgyRNqe1g==

AAJBXROfI+YgMwAAAJLbySgAAHIAAAAAAAEABHRlc3QAAnQ3AAMD/v4E/pb+HgaeTHyG

AAJBXR6fI+YgOAAAAMrbySgAAHIAAAAAAAEAAgAD//hLFQAABDU0NTEKMTU2NDUzOTk4Mvw96Vw=

'/*!*/;

### INSERT INTO `test`.`t7`

### SET

### @1=5451 /* INT meta=0 nullable=0 is_null=0 */

### @2='5451' /* STRING(150) meta=65174 nullable=1 is_null=0 */

### @3='1564539982' /* STRING(30) meta=65054 nullable=1 is_null=0 */

# at 684317642

#190731 10:50:40 server id 551953311 end_log_pos 684317673 CRC32 0x127f8ed8 Xid = 32777

COMMIT/*!*/;

# at 684317673

#190731 10:50:40 server id 551953311 end_log_pos 684317738 CRC32 0xafbad399 GTIDlast_committed=32697sequence_number=32702rbr_only=yes

/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;

SET @@SESSION.GTID_NEXT= '842db95c-453f-11e9-8d4f-94b86dd02e79:585207'/*!*/;

# at 684317738

#190731 10:50:40 server id 551953311 end_log_pos 684317810 CRC32 0xfe3810f4 Querythread_id=18exec_time=0error_code=0

SET TIMESTAMP=1564541440/*!*/;

BEGIN

/*!*/;

# at 684317810

#190731 10:50:40 server id 551953311 end_log_pos 684317883 CRC32 0x62ba7806 Rows_query

# insert into t3(name,name2) select 5426,1564539982

# at 684317883

#190731 10:50:40 server id 551953311 end_log_pos 684317934 CRC32 0x80e8cf34 Table_map: `test`.`t3` mapped to number 110

# at 684317934

#190731 10:50:40 server id 551953311 end_log_pos 684317990 CRC32 0x80b54665 Write_rows: table id 110 flags: STMT_END_F

BINLOG '

AAJBXR2fI+YgSQAAALvcySiAADFpbnNlcnQgaW50byB0MyhuYW1lLG5hbWUyKSBzZWxlY3QgNTQy

NiwxNTY0NTM5OTgyBni6Yg==

AAJBXROfI+YgMwAAAO7cySgAAG4AAAAAAAEABHRlc3QAAnQzAAMD/v4E/pb+HgY0z+iA

AAJBXR6fI+YgOAAAACbdySgAAG4AAAAAAAEAAgAD//gyFQAABDU0MjYKMTU2NDUzOTk4MmVGtYA=

'/*!*/;

### INSERT INTO `test`.`t3`

### SET

### @1=5426 /* INT meta=0 nullable=0 is_null=0 */

### @2='5426' /* STRING(150) meta=65174 nullable=1 is_null=0 */

### @3='1564539982' /* STRING(30) meta=65054 nullable=1 is_null=0 */

# at 684317990

#190731 10:50:40 server id 551953311 end_log_pos 684318021 CRC32 0x58f750f1 Xid = 32778

COMMIT/*!*/;

# at 684318021

#190731 10:50:40 server id 551953311 end_log_pos 684318086 CRC32 0x2af6e0ba GTIDlast_committed=32697sequence_number=32703rbr_only=yes

/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;

SET @@SESSION.GTID_NEXT= '842db95c-453f-11e9-8d4f-94b86dd02e79:585208'/*!*/;

# at 684318086

#190731 10:50:40 server id 551953311 end_log_pos 684318158 CRC32 0xaf142b3a Querythread_id=16exec_time=0error_code=0

SET TIMESTAMP=1564541440/*!*/;

BEGIN

/*!*/;

# at 684318158

#190731 10:50:40 server id 551953311 end_log_pos 684318231 CRC32 0x7a432157 Rows_query

# insert into t2(name,name2) select 5437,1564539982

# at 684318231

#190731 10:50:40 server id 551953311 end_log_pos 684318282 CRC32 0x5a67e440 Table_map: `test`.`t2` mapped to number 108

# at 684318282

#190731 10:50:40 server id 551953311 end_log_pos 684318338 CRC32 0x5ae88a17 Write_rows: table id 108 flags: STMT_END_F

BINLOG '

AAJBXR2fI+YgSQAAABfeySiAADFpbnNlcnQgaW50byB0MihuYW1lLG5hbWUyKSBzZWxlY3QgNTQz

NywxNTY0NTM5OTgyVyFDeg==

AAJBXROfI+YgMwAAAEreySgAAGwAAAAAAAEABHRlc3QAAnQyAAMD/v4E/pb+HgZA5Gda

AAJBXR6fI+YgOAAAAILeySgAAGwAAAAAAAEAAgAD//g9FQAABDU0MzcKMTU2NDUzOTk4MheK6Fo=

'/*!*/;

### INSERT INTO `test`.`t2`

### SET

### @1=5437 /* INT meta=0 nullable=0 is_null=0 */

### @2='5437' /* STRING(150) meta=65174 nullable=1 is_null=0 */

### @3='1564539982' /* STRING(30) meta=65054 nullable=1 is_null=0 */

# at 684318338

#190731 10:50:40 server id 551953311 end_log_pos 684318369 CRC32 0xb11ad492 Xid = 32776

COMMIT/*!*/;

# at 684318369

#190731 10:50:40 server id 551953311 end_log_pos 684318434 CRC32 0x003adc9a GTIDlast_committed=32697sequence_number=32704rbr_only=yes

/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;

SET @@SESSION.GTID_NEXT= '842db95c-453f-11e9-8d4f-94b86dd02e79:585209'/*!*/;

# at 684318434

#190731 10:50:40 server id 551953311 end_log_pos 684318506 CRC32 0x71308e9e Querythread_id=15exec_time=0error_code=0

SET TIMESTAMP=1564541440/*!*/;

BEGIN

/*!*/;

# at 684318506

#190731 10:50:40 server id 551953311 end_log_pos 684318579 CRC32 0x9f08db29 Rows_query

# insert into t6(name,name2) select 5462,1564539982

# at 684318579

#190731 10:50:40 server id 551953311 end_log_pos 684318630 CRC32 0x381e2a27 Table_map: `test`.`t6` mapped to number 113

# at 684318630

#190731 10:50:40 server id 551953311 end_log_pos 684318686 CRC32 0x126ee5e7 Write_rows: table id 113 flags: STMT_END_F

BINLOG '

AAJBXR2fI+YgSQAAAHPfySiAADFpbnNlcnQgaW50byB0NihuYW1lLG5hbWUyKSBzZWxlY3QgNTQ2

MiwxNTY0NTM5OTgyKdsInw==

AAJBXROfI+YgMwAAAKbfySgAAHEAAAAAAAEABHRlc3QAAnQ2AAMD/v4E/pb+HgYnKh44

AAJBXR6fI+YgOAAAAN7fySgAAHEAAAAAAAEAAgAD//hWFQAABDU0NjIKMTU2NDUzOTk4MuflbhI=

'/*!*/;

### INSERT INTO `test`.`t6`

### SET

### @1=5462 /* INT meta=0 nullable=0 is_null=0 */

### @2='5462' /* STRING(150) meta=65174 nullable=1 is_null=0 */

### @3='1564539982' /* STRING(30) meta=65054 nullable=1 is_null=0 */

# at 684318686

#190731 10:50:40 server id 551953311 end_log_pos 684318717 CRC32 0xeffd5044 Xid = 32779

COMMIT/*!*/;

# at 684318717

#190731 10:50:40 server id 551953311 end_log_pos 684318764 CRC32 0x78788de0 Rotate to mysql-bin.000027 pos: 4

SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;

DELIMITER ;

# End of log file

/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

```

> 注：

- 1、大事务的事务开始时间和大事务提交时间与测试打印的时间吻合。

- 2、大事务写binlog之前也有小事务写入

- 3、大事务的Xid远远小于下一个事务的Xid，且比它之前的事务还小，分析binlog发现是比这个文件所有事务的都小(因为(1)测试前flush logs了.(2)没有其他事务写入.(3)先执行的update【大事务】然后才insert【小事务】)。

- 4、大事务写完binlog后，也同样有一批小事务写入，最后一批小事务的last_commited是一样的

> 以上测试与线上的情况基本吻合，由此可知，binlog rotate不单单只是考虑最后一个事务的完整性，应该是考虑组提交的完整性。

### 其他

> autocommit=1

- 记录binlog的时候事务开始时间和commit时间是一样的

> autocommit=0

- 记录binlog的时候，事务开始时间是sql执行的时间，commit的时间是commit的时间不一样。

一键复制

编辑

Web IDE

原始数据

按行查看

历史

解析MySQL binlog --（6）XID_EVENT、ROTATE_EVENT、STOP_EVENT
帅的数说
03-25 2191
1、XID_EVENT当事务提交时，不论是statement还是row格式的binlog都会添加一个XID_EVENT作为事务的结束。该事件记录了该事务的ID。在mysql进行崩溃恢复时根据binlog中提交的情况来决定是否提交存储引擎中prepared状态的事务。2、ROTATE_EVENT当binlog文件大小达到max_binlog_size参数设置的值或执行flush logs命令时，bi...
mysql binlog events_使用SHOW binlog events查看binlog内容
weixin_42502408的博客
01-27 2017
MySQL Binary Log也就是常说的bin-log, ,是mysql执行改动产生的二进制日志文件,其主要作用有两个:* 数据回复* 主从数据库。用于slave端执行增删改，保持与master同步。1.开启binary log功能需要修改mysql的配置文件，本篇的实验环境是win7，配置文件为mysql安装目录\MySQL Server 5.1下的my.ini,添加一句log_bin = ...
记一次MySQL 5.7.10的binlog文件轮转(rotate)引起卡顿(block)出现慢日志的处理过程
xcc的博客
05-05 1397
描述： 程序反映当一个游戏服开服一段时间后，其使用的MySQL每隔一段时间都会出现几十条慢日志，慢日志集中在1到2秒内连续刷出，卡顿平均在60秒左右。一天当中每个时间段都有概率出现，即使是半夜3,4点没什么玩家的时候。 定位(trouble troubleshooting)： 根据描述，基本排除是程序代码的问题，因为游戏高峰期打世界BOSS的时候（每天中午12点玩家最活跃的时候）都不会...
binlog mysql_MySQL binlog格式解析
weixin_34626779的博客
01-18 304
binlog想必大家都不陌生，在主从复制或者某些情况下的数据恢复会用到。由于binlog是二进制数据，要查看一般都借助mysqlbinlog工具。这篇笔记分析了binlog格式，希望能够了解下mysqlbinlog工具背后所做的事情。1.什么时候写binlog在说明什么时候写binlog前，先简单介绍下binlog的用途。binlog是二进制日志文件，用于记录mysql的数据更新或者潜在更新(比如...
mysql binlog rotate_binlog rotate引发的MySQL阻塞事件
weixin_33514300的博客
01-19 229
背景在大型MySQL集群增加了新的库，运行正常(没有开启GTID)。几天后将新加入的库开启GTID。MySQL版本：5.7.19故障现象变更后，当业务压力开始上升，发现其中一个节点以大概半小时的频率，业务会间断性地发生阻塞。分析过程1.观察故障现象根据业务研发同事描述，大概每半小时发生一次故障。等到故障发生时，观测到以下现象：a.show processlist发现有4000左右正在执行的inse...
mysql binlog rotate_mysql binlog日志存储格式
weixin_34632164的博客
01-19 194
MySQL对于binlog的处理是以事件为单位的，每一次DML操作可能会产生多次事件，例如对于 innodb 存储引擎，会额外产生一条 query_event(事务的begin语句)和 xid_event(事务提交)。那么我们如何获取到这些事件呢?1. 发送DUMP包首先，我们知道 MySQL 本身就带有 replication 的机制，我们需要伪造一个 slave，向 master 注册，这样的...
mysql binlog事件 Rotate Event和Stop
arkblue的专栏
01-26 4699
top_log_event/STOP_EVENT A Stop_log_event is written under these circumstances: A master writes the event to the binary log when it shuts down A slave writes the event to the relay log when it shut
mysql binlog events_MySQL binlog event 详解
weixin_39768247的博客
01-19 621
我也是只菜鸡，blog写的不对或者不严谨的地方还请大伙指出来，我及时改正，免得误人子弟。实验环境：CentOS7.3.1611 + MySQL社区版 5.7.19参考：小菜鸟DBA的微信公众号推送官方文档：3个在线工具：binlog实际上由一个个不同类型的binlog event组成，每个binlog event还包含了event header部分和event data部分(可选)。【注意：每个e...
读取mysql binlog event_MySQL Binlog(四)—— MySQL binlog event解析——基础知识
weixin_33324197的博客
02-12 416
MySQL Binlog(四)—— MySQL binlog event解析——基础知识前言MySQL复制实质上就是讲binlog同步到从库上进行应用，前面的文章已经讲了如何建立复制连接，从这篇文章开始，我们来讲讲binlog里面的内容，看看主从之间同步具体同步了哪些内容，首先会介绍一些关于binlog event的基础知识，之后的文章中会详细对binlog event进行分析。event基础知识...
mysql binlog加密_MySQL · 引擎特性 · Binlog encryption 浅析
weixin_42195569的博客
02-05 1214
背景介绍为了保障数据安全，MySQL 在 5.7 版本就支持了 InnoDB 表空间加密，之前写了一篇月报介绍过，参考InnoDB 表空间加密。文章开头也提到过，MariaDB 除了对表空间加密，也可以对 redo log 和 binlog 加密，本质上 redo log 和 binlog 中也保存着明文的数据，如果文件被拖走数据也有丢失的风险，因此在 MySQL 8.0 中也支持两种日志的加密，...
mysql5.7 group commit 关于binlog文件切换(rotate)的笔记
qhgxinxing的博客
05-13 356
@[TOC](mysql5.7 group commit 关于binlog文件切换(rotate)的笔记) 在组提交的过程进入orderred_commit 函数 对binlog文件切换(rotate)的记录 有事务提交完成 此函数判断增加with_xid 确定为true，在写binglog 中写入 binary_log::XID_EVENT int binlog_cache_data::write_event(THD *thd, Log_event *ev) if (ev->get_type_cod
MySQL logrotate配置
FaN()
06-07 1491
MySQL logrotate配置vi /etc/logrotate.d/mysql /data/log/mysql/mysql-error.log { # create 600 mysql mysql notifempty daily rotate 3 missingok compress p
mysql binlog rotate_记一次MySQL 5.7.10的binlog文件轮转(rotate)引起卡顿(block)出现慢日志的处理过程...
weixin_42352453的博客
02-07 361
描述：程序反映当一个游戏服开服一段时间后，其使用的MySQL每隔一段时间都会出现几十条慢日志，慢日志集中在1到2秒内连续刷出，卡顿平均在60秒左右。一天当中每个时间段都有概率出现，即使是半夜3,4点没什么玩家的时候。定位(trouble troubleshooting)：根据描述，基本排除是程序代码的问题，因为游戏高峰期打世界BOSS的时候(每天中午12点玩家最活跃的时候)都不会出现慢日志，就算再...
53.MySQL-Utilities工具包之-mysqlbinlogrotate日志切换
weixin_43346403的博客
02-21 250
mysqlbinlogrotate 日志切换
MySQL log rotate配置
最新发布
不积跬步，无以至千里；不积小流，无以成江海。
05-09 481
`logrotate` 是 Linux 系统中用于管理和轮换日志文件的实用工具。它旨在自动管理日志文件的增长，避免日志文件变得过大，从而节省磁盘空间并防止单个日志文件占用过多空间。
配置mysql的 log rotate
wgz7747147820的博客
04-25 1294
mysql的error log还有general log等需要进行切割。可以结合logrotate进行log 切割 拷贝support_files下的mysql-log-rotate文件到/etc/logrotate.d/目录下，然后将权限修改为644 需要对mysql-log-rotate的内容继续修改已适应文件所在位置及切割的要求 [root@rws1270149 logrotate.d]# ...
mysql relay log和binlog 小结
cke63021的博客
11-29 794
今天突然mysql数据库的一个表的数据少了很多，我想着通过查看日志来判断针对这个表到底做了那些操作，然后再有针对性的去恢复，可是直接看binlog(二进制的形式)发现很乱，看不清楚，于是上网查询得知，需要先通过mysqlb...
多master mysql_使用 Rotate Master 实现MySQL 多主复制
weixin_29611573的博客
02-05 154
背景：众所周知，MySQL只支持一对多的主从复制，而不支持多主(multi-master)复制。当然，5.6的GUID功能的出现也带来了multi-master的无限可能，不过这个已经是题外话了。本文主要介绍一种非实时的适用于各版本MySQL的multi-master方法。内容简介：基本原理就是通过SP记录当前 master-log的name和pos记录到表中，然后读取下一个master记录，执行...
mysql的logrotate脚本
weixin_34392843的博客
02-23 107
随着业务量的增加和时间的推移mysql的日志势必会越来越多、越来越大,那么就要用系统的logrotate轮替mysql的日志（logrotate可以参看:http://jim123.blog.51cto.com/4763600/1880582），当然平时用的mysql都是二进制包部署安装的，其实mysql的二进制包中的support-files文件夹里就有提供mysql...
MySQL binlog配置：binlog_do_db与binlog_ignore_db详解
"MySQL binlog_ignore_db 参数的使用方法" MySQL 的 binlog（二进制日志）功能是数据库复制和恢复的重要组成部分，它记录了对数据库的所有改变操作，如 DDL（Data Definition Language）和 DML（Data Manipulation ...
评论
添加红包

请填写红包祝福语或标题

个

红包个数最小为10个

元

红包金额最低5元

当前余额3.43元 前往充值 >
需支付：10.00元
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付元
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明：

1.余额是钱包充值的虚拟货币，按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载，可以购买VIP、付费专栏及课程。

余额充值