Binlog

作者：杨彩琳 爱可生华东交付部DBA，次要负责MySQL日常问题解决及DMP产品反对。喜好跳舞，追剧。 本文起源：原创投稿 *爱可生开源社区出品，原创内容未经受权不得随便应用，转载请分割小编并注明起源。 前言大家在平时运维过程中应该都理解过或者应用过一些 binlog 解析工具，比方明天要介绍的 my2sql 和 binlog2sql 。my2sql 是基于 my2fback 、binlog_rollback 工具二次开发而来的（go语言），binlog2sql 是 python 语言开发的 mysql binlog 解析工具，两者都能够通过解析 binlog 文件，生成原始 SQL ，回滚SQL ，去除主键的 insert sql 等，而后实现数据疾速闪回，主从切换后的数据弥补等性能。 既然两个工具都能够实现解析 binlog 的性能，那么它们两个之间咱们该如何来抉择呢？请追随小编往下看“my2sql与binlog2sql之间的battle”吧。 主要参数简介【这里只列举了几个罕用的参数，有其余需要的参数可进入链接中查看】 my2sql参数参数解释-moderepl：伪装成从库从主库获取 binlog 文件；file：从本地文件系统获取 binlog 文件，默认repl-local-binlog-file 当指定当指定-mode=file参数时，须要指定 -local-binlog-file binlog 文件相对路径或绝对路径-sql要解析的 sql 类型，可选参数 insert ，update ，delete ，默认全副解析-file-per-table为每个表生成一个 sql 文件-output-dir将生成的后果寄存到指定目录-threads线程数，默认2个，反对并发-work-type2sql：生成原始 sql ，rollback ：生成回滚 sql ，stats：只统计 DML 、事务信息binlog2sql参数参数解释--stop-never继续解析 binlog ，默认 false ，同步至执行命令的最新 binlog 地位-B，--flashback生成回滚 sql ，可解析大文件，不受内存限度，默认 false ，与 stop-never 或 no-primary-key 不能同时增加--start-file起始解析文件，只需文件名，无需全门路--start-position/--start-pos起始解析地位。默认为 start-file 的起始地位。--stop-file/--end-file终止解析文件。默认为 start-file 同一个文件。若解析模式为 stop-never ，此选项生效。--stop-position/--end-pos终止解析地位。可选。默认为 stop-file 的最末地位；若解析模式为 stop-never ，此选项生效。--sql-type只解析指定类型，反对 INSERT ，UPDATE ，DELETE 。多个类型用空格隔开，如--sql-type INSERT DELETE 。默认为增删改都解析。用了此参数但没填任何类型，则三者都不解析。battle 之规范 sql 解析【解析2G大小的同一binlog文件】环境筹备：## 查看mysql的相干参数设置mysql> select @@server_id,@@binlog_format,@@binlog_row_image,@@max_binlog_size,@@log_bin_basename;+-------------+-----------------+--------------------+-------------------+-----------------------------------+| @@server_id | @@binlog_format | @@binlog_row_image | @@max_binlog_size | @@log_bin_basename |+-------------+-----------------+--------------------+-------------------+-----------------------------------+| 46733 | ROW | FULL | 1073741824 | /data/mysql/3309/binlog/mysql-bin |+-------------+-----------------+--------------------+-------------------+-----------------------------------+1 row in set (0.00 sec)## 应用sysbench创立测试数据表[root@10-186-61-119 ~]# sysbench /usr/share/sysbench/oltp_read_write.lua --mysql-host=10.186.61.119 \--mysql-port=3309 --mysql-user=root --mysql-password=root --mysql-db=test --table-size=2000000 --tables=1 \--threads=50 --db-ps-mode=disable --auto_inc=off --report-interval=3 --max-requests=0 --time=20 \--percentile=95 --skip_trx=off --mysql-ignore-errors=6002,6004,4012,2013,4016,1062 --create_secondary=off preparesysbench 1.0.17 (using system LuaJIT 2.0.4) Initializing worker threads... Creating table 'sbtest1'...Inserting 2000000 records into 'sbtest1'## 应用sysbench对测试表进行压测，生成2G左右binlog数据[root@10-186-61-119 ~]# sysbench /usr/share/sysbench/oltp_read_write.lua --mysql-host=10.186.61.119 \--mysql-port=3309 --mysql-user=root --mysql-password=root --mysql-db=test --table-size=2000000 --tables=1 \--threads=50 --db-ps-mode=disable --auto_inc=off --report-interval=3 --max-requests=0 --time=180 \--percentile=95 --skip_trx=off --mysql-ignore-errors=6002,6004,4012,2013,4016,1062 --create_secondary=off runsysbench 1.0.17 (using system LuaJIT 2.0.4) Running the test with following options:Number of threads: 50Report intermediate results every 3 second(s)Initializing random number generator from current time Initializing worker threads... Threads started!## 应用my2sql与binlog2sql解析mysql-bin.000013,mysql-bin.000014[root@10-186-61-119 binlog]# lltotal 4579116-rw-r----- 1 mysql mysql 209 Aug 3 14:17 mysql-bin.000010-rw-r----- 1 mysql mysql 1073760482 Aug 3 14:32 mysql-bin.000011-rw-r----- 1 mysql mysql 1074119415 Aug 3 14:36 mysql-bin.000012-rw-r----- 1 mysql mysql 1073822542 Aug 3 15:53 mysql-bin.000013-rw-r----- 1 mysql mysql 1074588226 Aug 3 16:15 mysql-bin.000014-rw-r----- 1 mysql mysql 392707488 Aug 3 16:16 mysql-bin.000015-rw-r----- 1 mysql mysql 246 Aug 3 16:15 mysql-bin.indexmy2sql 解析过程## 1 thread：应用脚本实现间断解析两个binlog的性能[root@10-186-61-119 my2sql]# cat /root/sql.sh#! /bin/bashdate;my2sql -user root -password root -host 10.186.61.119 -port 3309 -mode file -local-binlog-file /data/mysql/3309/binlog/mysql-bin.000013 -work-type 2sql \-start-file /data/mysql/3309/binlog/mysql-bin.000013 -threads 1 \-output-dir /data/my2sql/1thread/13 > /data/my2sql/1thread/13/output;my2sql -user root -password root -host 10.186.61.119 -port 3309 -mode file \-local-binlog-file /data/mysql/3309/binlog/mysql-bin.000014 -work-type 2sql \-start-file /data/mysql/3309/binlog/mysql-bin.000014 -threads 1 \-output-dir /data/my2sql/1thread/14 > /data/my2sql/1thread/14/output[root@10-186-61-119 ~]# ./sql.shThu Aug 4 17:17:24 CST 2022## 查看解析后果[root@10-186-61-119 13]# pwd/data/my2sql/1thread/13[root@10-186-61-119 13]# lltotal 347088-rw-r--r-- 1 root root 107 Aug 4 17:17 biglong_trx.txt-rw-r--r-- 1 root root 7488 Aug 4 17:24 binlog_status.txt-rw-r--r-- 1 root root 355389762 Aug 4 17:24 forward.13.sql ## 规范sql文件-rw-r--r-- 1 root root 9965 Aug 4 17:24 output[root@10-186-61-119 13]# cd ../14 && lltotal 577564-rw-r--r-- 1 root root 107 Aug 4 17:24 biglong_trx.txt-rw-r--r-- 1 root root 3312 Aug 4 17:28 binlog_status.txt-rw-r--r-- 1 root root 591403854 Aug 4 17:28 forward.14.sql ## 规范sql文件-rw-r--r-- 1 root root 9877 Aug 4 17:28 output ## 查看mysql-bin.000014的解析输入，实现工夫为17:28。my2sql单线程解析完2G左右的binlog文件大略须要11分钟[root@10-186-61-119 14]# less output......[2022/08/04 17:28:35] [info] file.go:71 finish parsing binlog from local files[2022/08/04 17:28:35] [info] stats_process.go:266 exit thread to analyze statistics from binlog[2022/08/04 17:28:35] [info] events.go:185 exit thread 1 to generate redo/rollback sql[2022/08/04 17:28:35] [info] events.go:274 finish writing redo/forward sql into file[2022/08/04 17:28:35] [info] events.go:277 exit thread to write redo/rollback sql into file## 4 thread：应用脚本实现间断解析两个binlog的性能【脚本内容与1 thread执行的统一，只需更改线程数即可，后续不再冗余展现】# 执行解析binlog语句[root@10-186-61-119 ~]# ./sql.shThu Aug 4 17:32:52 CST 2022# 查看mysql-bin.000014的解析输入，实现工夫为17:44。my2sql 4线程并发解析完2G左右的binlog文件大略须要12分钟[root@10-186-61-119 14]# less output。。。。。。。。[2022/08/04 17:44:42] [info] file.go:71 finish parsing binlog from local files[2022/08/04 17:44:42] [info] stats_process.go:266 exit thread to analyze statistics from binlog[2022/08/04 17:44:42] [info] events.go:185 exit thread 4 to generate redo/rollback sql[2022/08/04 17:44:42] [info] events.go:185 exit thread 2 to generate redo/rollback sql[2022/08/04 17:44:42] [info] events.go:185 exit thread 3 to generate redo/rollback sql[2022/08/04 17:44:42] [info] events.go:185 exit thread 1 to generate redo/rollback sql[2022/08/04 17:44:42] [info] events.go:274 finish writing redo/forward sql into file[2022/08/04 17:44:42] [info] events.go:277 exit thread to write redo/rollback sql into file## 6thread：应用脚本实现间断解析两个binlog的性能# 执行解析binlog语句[root@10-186-61-119 ~]# ./sql.shThu Aug 4 17:46:31 CST 2022# 查看mysql-bin.000014的解析输入，实现工夫为18:00。my2sql 6线程并发解析完2G左右的binlog文件大略须要14分钟[root@10-186-61-119 14]# less output。。。。。。。。[2022/08/04 18:00:11] [info] file.go:71 finish parsing binlog from local files[2022/08/04 18:00:11] [info] events.go:185 exit thread 6 to generate redo/rollback sql[2022/08/04 18:00:11] [info] stats_process.go:266 exit thread to analyze statistics from binlog[2022/08/04 18:00:11] [info] events.go:185 exit thread 1 to generate redo/rollback sql[2022/08/04 18:00:11] [info] events.go:185 exit thread 2 to generate redo/rollback sql[2022/08/04 18:00:11] [info] events.go:185 exit thread 5 to generate redo/rollback sql[2022/08/04 18:00:11] [info] events.go:185 exit thread 4 to generate redo/rollback sql[2022/08/04 18:00:11] [info] events.go:185 exit thread 3 to generate redo/rollback sql[2022/08/04 18:00:11] [info] events.go:274 finish writing redo/forward sql into file[2022/08/04 18:00:11] [info] events.go:277 exit thread to write redo/rollback sql into file## 8thread：应用脚本实现间断解析两个binlog的性能# 执行解析binlog语句[root@10-186-61-119 ~]# ./sql.shThu Aug 4 18:01:54 CST 2022# 查看mysql-bin.000014的解析输入，实现工夫为18:18。my2sql 8线程并发解析完2G左右的binlog文件大略须要17分钟[root@10-186-61-119 14]# less output。。。。。。。。[2022/08/04 18:18:51] [info] file.go:71 finish parsing binlog from local files[2022/08/04 18:18:51] [info] stats_process.go:266 exit thread to analyze statistics from binlog[2022/08/04 18:18:51] [info] events.go:185 exit thread 2 to generate redo/rollback sql[2022/08/04 18:18:51] [info] events.go:185 exit thread 6 to generate redo/rollback sql[2022/08/04 18:18:51] [info] events.go:185 exit thread 4 to generate redo/rollback sql[2022/08/04 18:18:51] [info] events.go:185 exit thread 1 to generate redo/rollback sql[2022/08/04 18:18:51] [info] events.go:185 exit thread 8 to generate redo/rollback sql[2022/08/04 18:18:51] [info] events.go:185 exit thread 5 to generate redo/rollback sql[2022/08/04 18:18:51] [info] events.go:185 exit thread 3 to generate redo/rollback sql[2022/08/04 18:18:51] [info] events.go:185 exit thread 7 to generate redo/rollback sql[2022/08/04 18:18:51] [info] events.go:274 finish writing redo/forward sql into file[2022/08/04 18:18:51] [info] events.go:277 exit thread to write redo/rollback sql into filebinlog2sql 解析过程## 应用脚本实现间断解析两个binlog的性能【--stop-never能够实现主动间断解析binlog文件，目前最新的binlog是15，然而为了与my2sql解析效率进行比照，所以不必这个参数】[root@10-186-61-119 ~]# cat binlog.sh#! /bin/bashdate;python /data/binlog2sql/binlog2sql/binlog2sql.py -h10.186.61.119 -P3309 -uroot -p'root' \--start-file='mysql-bin.000013' > /tmp/binlog13.sql;python /data/binlog2sql/binlog2sql/binlog2sql.py -h10.186.61.119 -P3309 -uroot -p'root' \--start-file='mysql-bin.000014' > /tmp/binlog14.sql;date;# 执行解析binlog语句[root@10-186-61-119 ~]# ./binlog.sh binlg2sql解析完2G左右的binlog文件大略须要54分钟 Wed Aug 3 17:53:59 CST 2022Wed Aug 3 18:47:08 CST 2022# 查看解析后果[root@10-186-61-119 ~]# ll /tmp/total 1688232-rw-r--r-- 1 root root 859359140 Aug 3 18:27 binlog13.sql-rw-r--r-- 1 root root 869387465 Aug 3 18:47 binlog14.sqlbattle后果如下表所示，从解析效率来看，my2sql更胜一筹 ...

作者：杨小云 爱可生数据库工程师，负责 MySQL 日常保护及 DMP 产品反对。善于mysql故障解决。 本文起源：原创投稿 *爱可生开源社区出品，原创内容未经受权不得随便应用，转载请分割小编并注明起源。 场景：客户误删了一张表，所以 想复原某张表的数据，冀望复原到删除之前的数据。 前提：数据库误删某表复原办法，上面介绍的的办法是针对每天有备份的数据库和开启 binlog 日志的。 阐明：本文中的测试库为 test 数据库，测试表是 test 中 student 表。 一、开启 binlog 日志，并备份数据1.查看数据库是否开启binlog日志 如果没有开启，须要上面的办法进行开启 （1）在linux零碎下，批改/etc/my.cnf文件 #编辑模式进入/etc/my.cnfvi /etc/my.cnf# i开始进行编辑# 在#log bin 前面增加内容server_id=2log_bin = mysql-binbinlog_format = ROWexpire_logs_days = 30log_bin_basename= /数据库实例装置目录/log/binlog/端口号/mysql-bin log_bin_index=/数据库实例装置目录/log/binlog/端口号/mysql-bin.index# esc 退出编辑，shift+:保留（2）重启 mysql 服务 systemctl restart mysqld 到这里曾经开启 binlog 了，能够用查看命令看一下是否开启 2. 查看一下数据表中的数据 3. 备份数据备份命令格局： mysqldump [选项] 数据库名 [表名] > 脚本名mysqldump [选项] --数据库名 [选项 表名] > 脚本名mysqldump [选项] --all-databases [选项] > 脚本名（1）备份所有数据库 ...

作者：陈伟 爱可生数据库工程师，负责MySQL日常保护及故障解决。 本文起源：原创投稿 *爱可生开源社区出品，原创内容未经受权不得随便应用，转载请分割小编并注明起源。 1.故障形容前一段时间客户反馈复制报错 1236 ，依据报错提醒该报错为从库读取到了主库不存在的 binlog 日志，导致复制中断，报错截图如下，须要帮忙剖析为什么会报错 Could not open log file 起因。 2.故障剖析阐明：思考客户信息敏感性，以下剖析过程均在测试环境模拟，数据库版本 5.7.31 ，GTID 启用。 2.1.先登录从库查看报错信息 发现从库的 io 线程断了，并报错：Got fatal error 1236 from master when reading data from binary log: 'Could not open log file' ，从字面意思不难理解，无奈从主库获取到 binlog 日志，GTID 进行在 828415 ，查看从库 error 日志报错如下： 依据从库报错信息，下一步咱们去主库查看主库的 binlog 信息和 error 日志，看主库 binlog 是否有失落的状况。 2.2.查看主库 binlog 信息，以及 error 日志登录主库查看 binlog 日志列表以及 index 索引文件，发现主库的 binlog 是间断的没有问题，但在查看 mysql-bin.index 文件的时候发现有记录两个 mysql-bin.000006 ，然而理论只有一个 mysql-bin.000006 文件，先记着这个奇怪的景象。 ...

作者：余振兴 爱可生 DBA 团队成员，相熟 Oracle、MySQL、MongoDB、Redis，最近在盘 TiDB，善于架构设计、故障诊断、数据迁徙、灾备构建等等。负责解决客户 MySQL 及我司自研 DMP 数据库治理平台日常运维中的问题。热衷技术分享、编写技术文档。 本文起源：原创投稿 *爱可生开源社区出品，原创内容未经受权不得随便应用，转载请分割小编并注明起源。事件背景 事件背景客户反馈在晚间数据跑批后,查问相干表的数据时,发现该表的局部数据在数据库中不存在,从利用跑批的日志来看,跑批未报错,且可查到日志中明确显示过后那批数据已插入到数据库中,须要帮忙剖析这批数据失落的起因。备注:思考信息敏感性,以下剖析场景测试环境模拟,相干数据做以下阐明 波及的库表为demo.t_dba_info表失落的数据为insert into t_dba_info(name,age) values('zhenxing',20);这条记录故障剖析1. 先登录数据库确认该条记录是否存在显然,数据的确如客户所说,在数据库中不存在 2. 确认该条数据失落的工夫区间并解析binlog这里我为模仿环境,间接在主库解析,生产环境倡议都在从库解析防止对主库造成影响BINLOG_LIST='mysql-bin.000002 mysql-bin.000003 mysql-bin.000004 mysql-bin.000005 mysql-bin.000006 mysql-bin.000007'for binlog in ${BINLOG_LIST}do echo "====== ${binlog}" mysqlbinlog -vv ${binlog}|grep -iEw "zhenxing"done 能够看到咱们通过解析并搜寻zhenxing这条记录,的确发现数据插入了数据库中,所以接下来从惯例的思路来说咱们只须要持续解析binlog,找到是否有对该条记录做DELETE或UPDATE操作即可3. 解析binlog查看对这张表的批改操作过滤出哪些binlog对该表做了DELETE或UPDATE## 这里我通过已知的故障工夫区间将波及的binlog列出来做循环解析BINLOG_LIST='mysql-bin.000002 mysql-bin.000003 mysql-bin.000004 mysql-bin.000005 mysql-bin.000006 mysql-bin.000007'for binlog in ${BINLOG_LIST}do echo "====== ${binlog}" mysqlbinlog --no-defaults --base64-output=decode-rows -vv ${binlog} | awk '/###/ {if($0~/UPDATE|INSERT|DELETE/)count[$2" "$NF]++}END{for(i in count) print i,"\t",count[i]}' | column -t | sort -k2nr|grep -i t_dba_info done ...

作者：胡呈清 爱可生 DBA 团队成员，善于故障剖析、性能优化，集体博客：https://www.jianshu.com/u/a95...，欢送探讨。 本文起源：原创投稿 *爱可生开源社区出品，原创内容未经受权不得随便应用，转载请分割小编并注明起源。 常用命令1. 解析 binlog 排查问题如果只是解析进去查看，能够加 --base64-output=decode-rows 不显示行格局的内容：mysqlbinlog --no-defaults -vv --base64-output=decode-rows mysql-bin.000201 2. 解析指定 GTID 的事务用来剖析某个事务做了什么：mysqlbinlog --no-defaults -vv --base64-output=decode-rows --include-gtids='b0ca6715-7554-11ea-a684-02000aba3dad:614037' mysql-bin.000199 3. 解析指定范畴的 binloga. 工夫范畴 --start-datetime、--stop-datetime 解析出指定工夫范畴内的 binlog，这个只适宜粗略的解析，不精准，因而不要用来回放 binlog。有个小技巧：如果只能确定大略的工夫范畴，而且不确定在哪个 binlog 中，能够间接解析多个 binlog。比方大略在 11:20-12:00 内做了个表删除操作，但这个工夫内有多个 binlog，能够这样： mysqlbinlog --no-defaults -vv --base64-output=decode-rows --start-datetime='2020-08-18 11:20:00' --stop-datetime='2020-08-18 12:00:00' mysql-bin.000203 mysql-bin.000204 mysql-bin.000205 b. 偏移量范畴 --start-position、--stop-position 解析 binlog 指定偏移量范畴内的 binlog。如果同时指定了 --start-position 和 --stop-position，并且是解析多个 binlog，则 --start-position 只对第一个 binlog 失效，--stop-position 只对最初一个 binlog 失效。 这个罕用场景是：曾经解析过一次 binlog 并获得指标事务的 起始 position 后，准确的解析这一段 binlog： ...

简介： PolarDB-X 2.0 针对数据孤岛问题提供了全局 Binlog 能力，该能力为上游生态提供了与 MySQL Binlog 完全一致的增量日志生产体验。针对数据损坏问题提供了实例级、表级、SQL 级和行级等不同粒度的数据恢复能力，包含一致性备份复原、表回收站、SQL 闪回、Flashback Query 等。 背景咱们作为开发者都理解或相熟后盾零碎，后盾零碎能够形象为两个组成部分：一个是业务零碎，该局部负责解决零碎的业务逻辑，在现代化的架构中，该局部通常设计成可程度扩大的无状态节点；另一个是数据库系统，该局部负责存储系统的状态，这其中便包含最外围的业务数据。 站在数据库的视角，数据的流入包含两个局部，一个是业务零碎的实时写入，这是外围数据起源的次要局部；另一个是从上游数据系统一次性或周期性导入的数据。因为这些外围数据在这里首次产生，所以这个数据库也被称为 SSOT（Single Source of Truth）。 SSOT 是后盾零碎中最重要的数据资产，那么随之便产生两个问题须要妥善处理。第一个问题是，作为最重要的资产，通常咱们须要将这些数据实时同步到其余零碎进行 BI 剖析等进一步的解决，如果没有这样的实时同步机制，那么这份数据将成为数据孤岛。第二个问题是，这份数据可能因为各种起因受到毁坏，比方硬件故障或软件 Bug 导致的数据损坏、不当操作引起的数据损坏、谬误 SQL 引起的数据错乱等，提供多种机制保障这份数据的平安显得十分必要。 全局 BinlogPolarDB-X 是一款高度兼容 MySQL 生态的分布式数据库产品，所以咱们首先来看下 MySQL 是如果解决数据孤岛问题的。 从 DB-Engines 排行榜能够看出，MySQL 的风行度比其余开源数据库的总和还要高，这意味着 MySQL 的生态十分凋敝，比方 MySQL 的上游零碎有 Kafka、MySQL 备节点、Canal 多种数据同步工具、Pulsar 等等。MySQL 通过 Binlog 机制实现了与上游零碎的实时增量数据同步。Binlog 能够看做是一个音讯队列，队列中按程序保留了 MySQL 中具体的增量变更信息，通过生产这个队列，上游零碎或工具实现了与 MySQL 的实时数据同步，这样的机制也称为 CDC（Change Data Capture），即增量数据捕获。 分布式数据库提供 CDC 能力绝对于单机有更高的复杂度。一个分布式数据库通常蕴含多个节点，这些节点会产生多个增量日志队列，那么上游如果要生产多个队列会波及几个问题。 因为是多个队列，那么上游生产时多个队列内变更事件的程序如何确定？分布式事务的变更可能波及多个队列，如果要保障生产时事务的完整性，那么如何发现并合并同一个事务的变更事件？零碎产生了扩缩容（也就是队列的增减）上游如何正确处理？DDL 会波及多个队列，上游如何准确辨认出每个队列 Schema 变动前后的地位并协调好生产进度？ 面对这些问题，分布式数据库的 CDC 能力须要在实现难度、反对个性、易用性等方面做 trade-off。通常来说，给上游提供多个队列、不保障事务完整性仅提供最终一致性、提供自定义格局的增量日志是一种较易实现的计划，但该计划会对上游生产提出更高的要求，比方要开发相应的生产代码或工具、须要思考多个队列的协同问题等。一种体验更敌对的形式是，通过提供与 MySQL Binlog 完全一致体验的 CDC 能力，让上游能够像生产 MySQL Binlog 一样通明的生产分布式数据库的增量变更，从而极大升高数据同步链路的搭建老本，这也是 PolarDB-X 2.0 采纳的计划，咱们称为全局 Binlog。 ...

Mysql Log 介绍[TOC] 参考: redo log 和 undo log 区别 一文理解InnoDB存储引擎 前言波及到的知识面有 Buffer Pool & Redo Log & Undo Log & BinLog & CheckPoint & 脏页。 如果每次数据更改操作都间接操作到磁盘上的话，当操作数量多起来的话，那么这些操作将变的很慢。为了进步操作之间的并发度，Mysql设计了缓存零碎。 一、Buffer Pool缓存池。当数据实现更改后，不会立马同步到磁盘上，而是先放到缓存池中。 二、Redo Log & Undo Log2.1 Redo Log为了避免零碎掉电后，缓存池中的数据不失落，即保障事务的持久性，特此记录一份数据批改之后的Log。例如，事务将 a 从 1 -> 2，b 从 4 -> 3，那么 Log 会记录 a:2, b:3。 2.1.1 特点大小固定，能够通过命令设置innodb_log_write_ahead_size；写满之后，持续重头写，笼罩之前写的内容；2.1.2 CHECKPOINTCHECKPOINT的作用就是记录上次刷入磁盘截止的地位，这样就不必每次都刷整个 redo log了。 脏页：redo log 上与磁盘数据不同的局部叫脏页，即CHECKPOINT到本次文件光标地位所蕴含的数据。 2.1.3 用处解决了数据变动立马操作磁盘的问题，进步了速度，之后便能够依照策略将redo log的日志批改数据；当零碎掉电后，通过 redo log 进行数据恢复;2.1.4 Redo Log 刷入磁盘依照redo log上记录的数据变动，将磁盘数据更新。本文讲的所有redo log 刷入磁盘都是指，刷入从CHECKPOINT开始到以后文件光标完结的数据。 ...

问题：在小伙伴们学习的过程中，执行了一个 insert，而后发现了以下景象： 首先在 binlog 中，发现这条 SQL 运行了 2 秒 (上一问中, 咱们晓得 BEGIN 的 exec_time 等于事务第一个 SQL 的 exec_time，本例中就是 insert 的 exec_time) 但在慢日志中,发现这条 SQL 的 query_time 为 10 秒: 那么 binlog 和慢日志谁的工夫更精确一些？ 试验首先咱们依照第 02 问的步骤，筹备一个慢 IO 的设施，使读操作和写操作都提早 2000ms（在 02 问中是 100ms，须要调整 dmsetup 那一步的参数），此处省略步骤。 这是咱们的慢 IO 设施和挂载点： 宽油建设一个数据库： 下个 SQL 看看： 察看 binlog，binlog 认为 SQL 执行了 2 秒： 察看慢日志，慢日志认为 SQL 执行了 10 秒： ...

问题 一段 binlog 如上图，为什么这个 BEGIN 执行了 5 秒，是数据库卡了还是统计错了？ 试验先宽油做一个数据库： 为了试验不便，咱们改一下 mysql 的提示符，将命令行的以后工夫显示在下面， 将 binlog 格局改为 statement： 创立一个试验表： 跑一个事务： 解开对应的 binlog： 失去后果： 咱们看到三组工夫：1. 黄色局部：每个 binlog event 前都会带有一个工夫戳，这个工夫戳和咱们执行每个语句时的开始工夫对应（截图中会偶然偏差 1s，是因为 SQL 是手工敲的，须要一些工夫）2. 红色局部：exec_time，每个语句的 exec_time 与语句的执行工夫对应，本例中是与 sleep 的时长对应，而 BEGIN 语句的 exec_time 始终与第一个句子的执行工夫雷同，其起因是 BEGIN 是在第一个语句执行时，与第一个语句同时写入 binlog 的，这就引起了 exec_time 统计的偏差：BEGIN 的 exec_time 实际上是其后第一个语句的执行工夫。3. 每个语句前会有一个 SET TIMESTAMP，咱们都晓得其会影响语句中的工夫函数，比方 now() 函数的工夫基准。 咱们重做一次试验，验证一下手工 SET TIMESTAMP 的影响： 如上图，咱们扭转了 timestamp。来看一下 binlog 的体现： ...

作者：赵拂晓爱可生 MySQL DBA 团队成员，Oracle 10g OCM，MySQL 5.7 OCP，善于数据库性能问题诊断、事务与锁问题的剖析等，负责解决客户 MySQL 及我司自研 DMP 平台日常运维中的问题，对开源数据库相干技术十分感兴趣。本文起源：原创投稿*爱可生开源社区出品，原创内容未经受权不得随便应用，转载请分割小编并注明起源。前言大部分 DBA 应该都曾经相熟并应用过一些闪回工具，诸如：binlog2sql、MyFlash。 明天要介绍的是另一款基于 Go 编写的 binlog 解析工具：my2sql，他的同门师兄还有 my2fback、binlog_inspector（binlog_rollback）。 为什么不间接称其为闪回工具呢？因为闪回只是它其中一个性能，除此之外，还可用于从 binlog 中解析出执行过的 SQL 语句用于数据弥补，或者对线上执行的事务进行剖析（捕捉大/长事务）。 Github 地址：https://github.com/liuhr/my2sql 比照binlog2sql：Python 编写（执行时须要有 Python2.7、Python3.4+ 的环境），用于生成回滚/前滚 SQL 进行数据恢复/弥补MyFlash：C 语言编写（须要动静编译成二级制脚本后执行），用于生成反向 binlog 文件（二进制）进行数据恢复my2sql：Go 语言编写（可间接下载 linux 二进制版本执行），除了闪回，还提供了前滚和事务剖析的性能主要参数-work-type：指定工作类型（前滚、闪回、事务剖析），非法值别离为：2sql（默认）、rollback、stats-sql：过滤 DML 语句的类型，非法值为：insert、update、delete-ignorePrimaryKeyForInsert：对于 work-type 为 2sql 的 insert 操作，疏忽主键（适宜大量数据导入的场景）-big-trx-row-limit int：断定为大事务的阈值（默认 500 行），非法值区间：10-30000 行-long-trx-seconds int：断定为长事务的阈值（默认 300 秒），非法值区间：1-3600 秒-databases：过滤库，默认为全副库-tables：过滤表，默认为全副表-start-file：指定开始的 binlog 文件-start-pos：指定 binlog 文件中开始的点位-start-datetime：指定开始的工夫-stop-datetime：指定完结的工夫-output-dir：指定文件生成目录-output-toScreen：指定输入到屏幕-tl：指定时区（time location），默认为 local（Asia/Shanghai）利用场景场景 1：闪回 DML 误操作数据-- 创立测试表mysql> show create table t\G*************************** 1. row *************************** Table: tCreate Table: CREATE TABLE `t` ( `id` int(11) NOT NULL AUTO_INCREMENT, `k` int(11) NOT NULL DEFAULT '0', `c` char(120) NOT NULL DEFAULT '', `pad` char(60) NOT NULL DEFAULT '', PRIMARY KEY (`id`), KEY `k_1` (`k`)) ENGINE=InnoDB AUTO_INCREMENT=10001 DEFAULT CHARSET=utf81 row in set (0.00 sec)mysql> select count(*) from t;+----------+| count(*) |+----------+| 10000 |+----------+1 row in set (0.00 sec)-- 查看测试表校验值mysql> checksum table t;+-------+------------+| Table | Checksum |+-------+------------+| zlm.t | 1966401574 |+-------+------------+1 row in set (0.02 sec)-- 查看以后binlogmysql> show master status;+------------------+----------+--------------+------------------+----------------------------------------------+| File | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |+------------------+----------+--------------+------------------+----------------------------------------------+| mysql-bin.000003 | 15994082 | | | 1d7ef0f4-4593-11eb-9f04-02000aba3c3e:1-23123 |+------------------+----------+--------------+------------------+----------------------------------------------+1 row in set (0.00 sec)-- 删除5000条记录mysql> delete from t where id<5001;Query OK, 5000 rows affected (0.04 sec)-- 执行my2sql生成回滚语句（rollback模式）04:38 PM dmp1 (master) ~# ./my2sql -user zlm -password zlm -host 10.186.60.62 -port 3332 -work-type rollback -start-file mysql-bin.000003 -start-pos 15994082 --add-extraInfo -output-dir /tmp/my2sql_test[2020/12/25 16:38:17] [info] binlogsyncer.go:144 create BinlogSyncer with config {1113306 mysql 10.186.60.62 3332 zlm utf8 false false <nil> false Local false 0 0s 0s 0 false false 0}[2020/12/25 16:38:17] [info] events.go:58 start thread 1 to generate redo/rollback sql[2020/12/25 16:38:17] [info] events.go:58 start thread 2 to generate redo/rollback sql[2020/12/25 16:38:17] [info] events.go:208 start thread to write redo/rollback sql into file[2020/12/25 16:38:17] [info] binlogsyncer.go:360 begin to sync binlog from position (mysql-bin.000003, 15994082)[2020/12/25 16:38:17] [info] stats_process.go:166 start thread to analyze statistics from binlog[2020/12/25 16:38:17] [info] repl.go:15 start to get binlog from mysql[2020/12/25 16:38:17] [info] binlogsyncer.go:777 rotate to (mysql-bin.000003, 15994082)[2020/12/25 16:38:17] [info] events.go:242 finish processing mysql-bin.000003 16002473[2020/12/25 16:38:22] [info] repl.go:83 deadline exceeded.[2020/12/25 16:38:22] [info] repl.go:17 finish getting binlog from mysql[2020/12/25 16:38:22] [info] stats_process.go:266 exit thread to analyze statistics from binlog[2020/12/25 16:38:22] [info] events.go:183 exit thread 1 to generate redo/rollback sql[2020/12/25 16:38:22] [info] events.go:183 exit thread 2 to generate redo/rollback sql[2020/12/25 16:38:22] [info] events.go:257 finish writing rollback sql into tmp files, start to revert content order of tmp files[2020/12/25 16:38:22] [info] rollback_process.go:15 start thread 1 to revert rollback sql files[2020/12/25 16:38:22] [info] rollback_process.go:41 start to revert tmp file /tmp/my2sql_test/.rollback.3.sql into /tmp/my2sql_test/rollback.3.sql[2020/12/25 16:38:22] [info] rollback_process.go:156 finish reverting tmp file /tmp/my2sql_test/.rollback.3.sql into /tmp/my2sql_test/rollback.3.sql[2020/12/25 16:38:22] [info] rollback_process.go:25 exit thread 1 to revert rollback sql files[2020/12/25 16:38:22] [info] events.go:270 finish reverting content order of tmp files[2020/12/25 16:38:22] [info] events.go:275 exit thread to write redo/rollback sql into file-- 查看生成的文件04:40 PM dmp1 /tmp/my2sql_test# lltotal 1228-rw-r--r-- 1 root root 251 Dec 25 16:38 biglong_trx.txt-rw-r--r-- 1 root root 288 Dec 25 16:38 binlog_status.txt-rw-r--r-- 1 root root 1246880 Dec 25 16:38 rollback.3.sql## 其中rollback.x.sql就是咱们闪回数据须要的sql文件（x对应mysql-binlog.00000x的文件编号x），因为执行命令时只指定了binlog开始的地位，实例中后续执行的DML事务也都会被记录## 另外2个文件别离是从binlog中获取到的binlog状态和事务信息，之后的案例会具体展现阐明，此处略过-- 查看生成的回滚SQL文本文件04:42 PM dmp1 /tmp/my2sql_test# tail -5 rollback.3.sql INSERT INTO `zlm`.`t` (`id`,`k`,`c`,`pad`) VALUES (4,5027,'54133149494-75722987476-23015721680-47254589498-40242947469-55055884969-23675271222-20181439230-74473404563-55407972672','88488171626-98596569412-94026374972-58040528656-38000028170');INSERT INTO `zlm`.`t` (`id`,`k`,`c`,`pad`) VALUES (3,4990,'51185622598-89397522786-28007882305-52050087550-68686337807-48942386476-96555734557-05264042377-33586177817-31986479495','00592560354-80393027097-78244247549-39135306455-88936868384');INSERT INTO `zlm`.`t` (`id`,`k`,`c`,`pad`) VALUES (2,5025,'13241531885-45658403807-79170748828-69419634012-13605813761-77983377181-01582588137-21344716829-87370944992-02457486289','28733802923-10548894641-11867531929-71265603657-36546888392');INSERT INTO `zlm`.`t` (`id`,`k`,`c`,`pad`) VALUES (1,5015,'68487932199-96439406143-93774651418-41631865787-96406072701-20604855487-25459966574-28203206787-41238978918-19503783441','22195207048-70116052123-74140395089-76317954521-98694025897');# datetime=2020-12-25_16:33:30 database=zlm table=t binlog=mysql-bin.000003 startpos=15994218 stoppos=1600247305:10 PM dmp1 /tmp/my2sql_test# cat rollback.3.sql |grep "INSERT INTO"|wc -l5000## 能够看到，该闪回SQL文件中有5000个INSERT语句，正好对应之前删除的5000条记录## 闪回SQL文件中的“# datetime=...”这行的内容就是加了参数-add-extrainfo后退出的附加信息，能够获取每个语句执行的具体工夫和点位## 在理论状况中，从binlog中解析进去的事务会很简单，为了便于剖析，倡议加上过滤库、表的参数-databases和-tables，这样生成的SQL文件也会小很多-- 数据恢复（将误删数据导入）05:17 PM dmp1 (master) ~# mysql32 < /tmp/my2sql_test/rollback.3.sqlmysql: [Warning] Using a password on the command line interface can be insecure.05:19 PM dmp1 (master) ~# mysql32 -Ne "select count(*) from zlm.t;checksum table zlm.t;"mysql: [Warning] Using a password on the command line interface can be insecure.+-------+| 10000 |+-------++-------+------------+| zlm.t | 1966401574 |+-------+------------+## 5000条删除的数据导入表后，表的checksum与删除前统一，阐明该在表上没有进行过其余DML操作## 如果记录数统一而checksum不统一，则认为复原后的数据依然是不统一的，须要确认是否须要做更多的闪回操作场景 2：手动弥补主从异样切换后的数据不统一-- 用sysbench给一个继续写入01:34 AM dmp1 /usr/local/sysbench/share/sysbench# sysbench /usr/local/sysbench/share/sysbench/oltp_read_write.lua --db-driver=mysql --tables=1 --table_size=10000 --mysql-host=10.186.60.62 --mysql-port=3332 --mysql-db=zlm --mysql-user=zlm --mysql-password=zlm --report-interval=2 --threads=10 --time=600 --skip-trx=on --mysql-ignore-errors=1062,1213 --db-ps-mode=disable runsysbench 1.0.17 (using bundled LuaJIT 2.1.0-beta2)Running the test with following options:Number of threads: 10Report intermediate results every 2 second(s)Initializing random number generator from current timeInitializing worker threads...Threads started![ 2s ] thds: 10 tps: 712.84 qps: 12964.69 (r/w/o: 10095.03/2855.81/13.85) lat (ms,95%): 27.17 err/s: 5.44 reconn/s: 0.00[ 4s ] thds: 10 tps: 733.05 qps: 13289.89 (r/w/o: 10342.52/2939.79/7.57) lat (ms,95%): 28.16 err/s: 4.54 reconn/s: 0.00... 略-- 确认从库失常复制后进行IO线程mysql> show slave status\G*************************** 1. row *************************** Slave_IO_State: Waiting for master to send event Master_Host: 10.186.60.62 Master_User: zlm Master_Port: 3332 Connect_Retry: 60 Master_Log_File: mysql-bin.000013 Read_Master_Log_Pos: 60687481 Relay_Log_File: relay-bin.000009 Relay_Log_Pos: 60685775 Relay_Master_Log_File: mysql-bin.000013 Slave_IO_Running: Yes Slave_SQL_Running: Yes Replicate_Do_DB: Replicate_Ignore_DB: Replicate_Do_Table: Replicate_Ignore_Table: Replicate_Wild_Do_Table: Replicate_Wild_Ignore_Table: Last_Errno: 0 Last_Error: Skip_Counter: 0 Exec_Master_Log_Pos: 60685562 Relay_Log_Space: 594023093 Until_Condition: None Until_Log_File: Until_Log_Pos: 0 Master_SSL_Allowed: No Master_SSL_CA_File: Master_SSL_CA_Path: Master_SSL_Cert: Master_SSL_Cipher: Master_SSL_Key: Seconds_Behind_Master: 0Master_SSL_Verify_Server_Cert: No Last_IO_Errno: 0 Last_IO_Error: Last_SQL_Errno: 0 Last_SQL_Error: Replicate_Ignore_Server_Ids: Master_Server_Id: 623332 Master_UUID: 1d7ef0f4-4593-11eb-9f04-02000aba3c3e Master_Info_File: /data/mysql/mysql3332/data/master.info SQL_Delay: 0 SQL_Remaining_Delay: NULL Slave_SQL_Running_State: Reading event from the relay log Master_Retry_Count: 86400 Master_Bind: Last_IO_Error_Timestamp: Last_SQL_Error_Timestamp: Master_SSL_Crl: Master_SSL_Crlpath: Retrieved_Gtid_Set: 1d7ef0f4-4593-11eb-9f04-02000aba3c3e:58752-915239 Executed_Gtid_Set: 1d7ef0f4-4593-11eb-9f04-02000aba3c3e:1-915235 Auto_Position: 1 Replicate_Rewrite_DB: Channel_Name: Master_TLS_Version: 1 row in set (0.00 sec)mysql> stop slave io_thread;Query OK, 0 rows affected (0.01 sec)mysql> show slave status\G*************************** 1. row *************************** Slave_IO_State: Master_Host: 10.186.60.62 Master_User: zlm Master_Port: 3332 Connect_Retry: 60 Master_Log_File:mysql-bin.000013 Read_Master_Log_Pos: 78769827 Relay_Log_File: relay-bin.000009 Relay_Log_Pos: 78770040 Relay_Master_Log_File: mysql-bin.000013 Slave_IO_Running: No Slave_SQL_Running: Yes Replicate_Do_DB: Replicate_Ignore_DB: Replicate_Do_Table: Replicate_Ignore_Table: Replicate_Wild_Do_Table: Replicate_Wild_Ignore_Table: Last_Errno: 0 Last_Error: Skip_Counter: 0 Exec_Master_Log_Pos:78769827 Relay_Log_Space: 612105439 Until_Condition: None Until_Log_File: Until_Log_Pos: 0 Master_SSL_Allowed: No Master_SSL_CA_File: Master_SSL_CA_Path: Master_SSL_Cert: Master_SSL_Cipher: Master_SSL_Key: Seconds_Behind_Master: NULLMaster_SSL_Verify_Server_Cert: No Last_IO_Errno: 0 Last_IO_Error: Last_SQL_Errno: 0 Last_SQL_Error: Replicate_Ignore_Server_Ids: Master_Server_Id: 623332 Master_UUID: 1d7ef0f4-4593-11eb-9f04-02000aba3c3e Master_Info_File: /data/mysql/mysql3332/data/master.info SQL_Delay: 0 SQL_Remaining_Delay: NULL Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates Master_Retry_Count: 86400 Master_Bind: Last_IO_Error_Timestamp: Last_SQL_Error_Timestamp: Master_SSL_Crl: Master_SSL_Crlpath: Retrieved_Gtid_Set: 1d7ef0f4-4593-11eb-9f04-02000aba3c3e:58752-941653 Executed_Gtid_Set: 1d7ef0f4-4593-11eb-9f04-02000aba3c3e:1-941653 Auto_Position: 1 Replicate_Rewrite_DB: Channel_Name: Master_TLS_Version: 1 row in set (0.00 sec)-- 进行sysbench写入[ 120s ] thds: 10 tps: 820.27 qps: 14836.91 (r/w/o: 11540.32/3284.59/12.00) lat (ms,95%): 22.28 err/s: 4.00 reconn/s: 0.00[ 122s ] thds: 10 tps: 718.49 qps: 13009.74 (r/w/o: 10126.80/2874.44/8.50) lat (ms,95%): 24.83 err/s: 4.50 reconn/s: 0.00[ 124s ] thds: 10 tps: 781.74 qps: 14178.87 (r/w/o: 11029.89/3137.97/11.00) lat (ms,95%): 23.52 err/s: 6.50 reconn/s: 0.00^C## 此时主库的数据是比从库多的（能够看作是异步复制中的IO线程提早），假如又正好产生了高可用切换，从库被切成了主库，咱们须要手动弥补新主上缺失的这部分数据（如果高可用切换工具没有这部分实现逻辑的话）-- 确认后续（缺失）事务的起始点位从show slave status的输入，咱们能够获知以下信息：1、新主已执行过的事务汇合：1d7ef0f4-4593-11eb-9f04-02000aba3c3e:1-9416532、对应旧主上的点位：Master_Log_File:mysql-bin.000013Exec_Master_Log_Pos: 78769827-- 查看旧主以后GTID信息mysql> show master status;+------------------+-----------+--------------+------------------+------------------------------------------------+| File | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |+------------------+-----------+--------------+------------------+------------------------------------------------+| mysql-bin.000013 | 151283749 | | | 1d7ef0f4-4593-11eb-9f04-02000aba3c3e:1-1047585 |+------------------+-----------+--------------+------------------+------------------------------------------------+1 row in set (0.00 sec)## 相差了105932个事务，binlog从77M增长到150M左右-- 也能够离线解析binlog文件来确认file+pos的点位与GTID是否是对应/usr/local/mysql5732/bin/mysqlbinlog -vv --base64-output=decode-rows mysql-bin.000013|less... 略#201226 1:36:31 server id 623332 end_log_pos 78769827 CRC32 0xe5032fcf Xid = 4003981COMMIT/*!*/;# at78769827 //当1d7ef0f4-4593-11eb-9f04-02000aba3c3e:941653的事务COMMIT后，pos点位就停在这里，是统一的#201226 1:36:31 server id 623332 end_log_pos 78769892 CRC32 0x6cec07fc GTID last_committed=115069 sequence_number=115070 rbr_only=yes/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;SET @@SESSION.GTID_NEXT= '1d7ef0f4-4593-11eb-9f04-02000aba3c3e:941654'/*!*/;# at 78769892#201226 1:36:31 server id 623332 end_log_pos 78769963 CRC32 0x0b9b5557 Query thread_id=89 exec_time=0 error_code=0SET TIMESTAMP=1608917791/*!*/;BEGIN/*!*/;# at 78769963#201226 1:36:31 server id 623332 end_log_pos 78770228 CRC32 0x75e40978 Rows_query# INSERT INTO sbtest1 (id, k, c, pad) VALUES (5020, 5013, '79652507036-05590009094-10370692577-33401396318-81508361252-10613546461-82822929332-17272183925-71915791860-00345159222', '25450417435-19336936168-49193845527-09907338597-56878802246')# at 78770228#201226 1:36:31 server id 623332 end_log_pos 78770284 CRC32 0xfc0d0d16 Table_map: `zlm`.`sbtest1` mapped to number 204# at 78770284#201226 1:36:31 server id 623332 end_log_pos 78770509 CRC32 0xe1d44365 Write_rows: table id 204 flags: STMT_END_F### INSERT INTO `zlm`.`sbtest1`### SET### @1=5020 /* INT meta=0 nullable=0 is_null=0 */### @2=5013 /* INT meta=0 nullable=0 is_null=0 */### @3='79652507036-05590009094-10370692577-33401396318-81508361252-10613546461-82822929332-17272183925-71915791860-00345159222' /* STRING(360) meta=61032 nullable=0 is_null=0 */### @4='25450417435-19336936168-49193845527-09907338597-56878802246' /* STRING(180) meta=65204 nullable=0 is_null=0 */# at 78770509#201226 1:36:31 server id 623332 end_log_pos 78770540 CRC32 0x1adbcf14 Xid = 4003993COMMIT/*!*/;# at 78770540#201226 1:36:31 server id 623332 end_log_pos 78770605 CRC32 0x52d9646f GTID last_committed=115070 sequence_number=115071 rbr_only=yes/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;SET @@SESSION.GTID_NEXT= '1d7ef0f4-4593-11eb-9f04-02000aba3c3e:941655'/*!*/;# at 78770605#201226 1:36:31 server id 623332 end_log_pos 78770676 CRC32 0x7ed98e8d Query thread_id=85 exec_time=0 error_code=0SET TIMESTAMP=1608917791/*!*/;BEGIN/*!*/;# at 78770676#201226 1:36:31 server id 623332 end_log_pos 78770738 CRC32 0x28584bc5 Rows_query# UPDATE sbtest1 SET k=k+1 WHERE id=6248-- 生成前滚SQL（从mysql-bin.000013的78769827开始）01:55 PM dmp1 (master) ~# ./my2sql -user zlm -password zlm -host 10.186.60.62 -port 3332 -work-type 2sql -start-file mysql-bin.000013 -start-pos78769827 --add-extraInfo -output-dir /tmp/my2sql_test[2020/12/26 01:54:51] [info] binlogsyncer.go:144 create BinlogSyncer with config {1113306 mysql 10.186.60.62 3332 zlm utf8 false false <nil> false Local false 0 0s 0s 0 false false 0}[2020/12/26 01:54:51] [info] binlogsyncer.go:360 begin to sync binlog from position (mysql-bin.000013, 78769827)[2020/12/26 01:54:51] [info] events.go:208 start thread to write redo/rollback sql into file[2020/12/26 01:54:51] [info] events.go:58 start thread 1 to generate redo/rollback sql[2020/12/26 01:54:51] [info] events.go:58 start thread 2 to generate redo/rollback sql[2020/12/26 01:54:51] [info] stats_process.go:166 start thread to analyze statistics from binlog[2020/12/26 01:54:51] [info] repl.go:15 start to get binlog from mysql[2020/12/26 01:54:51] [info] binlogsyncer.go:777 rotate to (mysql-bin.000013, 78769827)[2020/12/26 01:54:51] [info] events.go:242 finish processing mysql-bin.000013 78770509[2020/12/26 01:54:52] [info] events.go:242 finish processing mysql-bin.000013 89256973[2020/12/26 01:54:53] [info] events.go:242 finish processing mysql-bin.000013 99742835[2020/12/26 01:54:54] [info] events.go:242 finish processing mysql-bin.000013 110229245[2020/12/26 01:54:55] [info] events.go:242 finish processing mysql-bin.000013 120715455[2020/12/26 01:54:56] [info] events.go:242 finish processing mysql-bin.000013 131201391[2020/12/26 01:54:57] [info] events.go:242 finish processing mysql-bin.000013 141687468[2020/12/26 01:55:03] [info] repl.go:83 deadline exceeded.[2020/12/26 01:55:03] [info] repl.go:17 finish getting binlog from mysql[2020/12/26 01:55:03] [info] stats_process.go:266 exit thread to analyze statistics from binlog[2020/12/26 01:55:03] [info] events.go:183 exit thread 1 to generate redo/rollback sql[2020/12/26 01:55:03] [info] events.go:183 exit thread 2 to generate redo/rollback sql[2020/12/26 01:55:03] [info] events.go:272 finish writing redo/forward sql into file[2020/12/26 01:55:03] [info] events.go:275 exit thread to write redo/rollback sql into file-- 查看生成的新文件01:54 AM dmp1 /tmp/my2sql_test# ll -lrttotal 25732-rw-r--r-- 1 root root 107 Dec 26 01:54 biglong_trx.txt-rw-r--r-- 1 root root 26339348 Dec 26 01:55 forward.13.sql-rw-r--r-- 1 root root 432 Dec 26 01:55 binlog_status.txt01:56 AM dmp1 /tmp/my2sql_test# cat binlog_status.txt binlog starttime stoptime startpos stoppos inserts updates deletes database table mysql-bin.000013 2020-12-26_01:36:31 2020-12-26_01:37:00 78770228 143726338 23713 47466 23715 zlm sbtest1 mysql-bin.000013 2020-12-26_01:37:01 2020-12-26_01:37:04 143726770 151283718 2755 5530 2753 zlm sbtest1 01:57 AM dmp1 /tmp/my2sql_test# cat biglong_trx.txt binlog starttime stoptime startpos stoppos rows duration tables-- 计算事务个数01:57 AM dmp1 /tmp/my2sql_test# mysql -Ne "select 23713+47466+23715+2755+5530+2753;"+--------+| 105932 |+--------+02:01 AM dmp1 /tmp/my2sql_test# cat forward.13.sql |grep INSERT|wc -l2646802:03 AM dmp1 /tmp/my2sql_test# cat forward.13.sql |grep UPDATE|wc -l5299602:03 AM dmp1 /tmp/my2sql_test# cat forward.13.sql |grep DELETE|wc -l2646802:04 AM dmp1 /tmp/my2sql_test# mysql32 -Ne "select 26468+52996+26468;"mysql: [Warning] Using a password on the command line interface can be insecure.+--------+| 105932 |+--------+01:56 AM dmp1 /tmp/my2sql_test# scp forward.13.sql 10.186.60.68:/tmpforward.13.sql 100% 25MB 140.9MB/s 00:00## 前滚SQL文件有26M，拷贝到新主（60.68）## 查看生成的binlog_status.txt文件，会统计每个时间段（POS）区间内相干库表所产生的DML次数## biglong_trx.txt文件记录的是大/长事务，此文件为空，阐明没有大/长事务## 由文件中记录的DML总执行次数可知，的确是执行了105932 个事务，与之前估算的统一-- 将差别数据导入新主02:05 AM dmp2 (master) ~# mysql32 < /tmp/forward.13.sql mysql: [Warning] Using a password on the command line interface can be insecure.02:05 AM dmp2 (master) ~#-- 查看从库的事务写入状况mysql> show slave status\G... 略 Retrieved_Gtid_Set: 1d7ef0f4-4593-11eb-9f04-02000aba3c3e:58752-941653 Executed_Gtid_Set: 1d7ef0f4-4593-11eb-9f04-02000aba3c3e:1-941653,3f4e72ab-46af-11eb-9bac-02000aba3c44:1-105932 //新主写入了105932个事务，与之前统计的值统一 Auto_Position: 1 Replicate_Rewrite_DB: Channel_Name: Master_TLS_Version: 1 row in set (0.00 sec)-- 校验旧主和新主的测试表## 旧主mysql> checksum table sbtest1;+-------------+-----------+| Table | Checksum |+-------------+-----------+| zlm.sbtest1 | 670442058 |+-------------+-----------+1 row in set (0.01 sec)## 新主mysql> checksum table zlm.sbtest1;+-------------+-----------+| Table | Checksum |+-------------+-----------+| zlm.sbtest1 | 670442058 |+-------------+-----------+1 row in set (0.02 sec)## 因为本次测试中仅仅是对sbtest1表执行了DML操作，能够认为新主缺失的数据曾经失去弥补## 在实在环境中，弥补数据可能会比拟麻烦一些，因为会波及到很多库表的操作，但原理是一样的场景 3：在线事务剖析3.1 筹备 ...

问题最近年底，大家的数据库常常跑批量大事务，会发现复制忽然断开，报错“心跳与本地信息不兼容”： 会是什么起因？ 试验咱们先来复现一下，再进行剖析。 宽油，做一对主从数据库： 咱们先造一个 500M 的空文件，下一步有用： 再制作一张大表，这里用到了之前的造表法，不同的是应用了一个 longblob 字段，让多数的几行记录就能占用很大的 binlog 空间，不便咱们前面做试验。 这里的 longblob 字段，用到了上一步咱们做的空文件， 这样咱们取得了一个行数较少，但体积很大的表。 当初起两个会话，一个事务造表 t2，一个事务造表 t3，并同时提交操作，以下举例其中一个事务： 这样就取得了一个超大的 binlog，一共 32G，前 16G 是一个事务，后 16G 是另一个事务。 小贴士一个事务超过 binlog 的限度大小（最大 1G），就会在事务后间接切换到新的 binlog。 在同一个 binlog 中，咱们想让一个超大事务后再记录一个事务，所以让两个事务同时提交，放在同一个提交组中。 查看一下 master 上的 GTID，最初两个事务别离是 25 和 26： 上面登录到 slave上，开始表演： 咱们先重置 GTID 和复制状态，而后骗 slave 说它曾经接到了 1-25 事务，要从 26 号事务开始传输，也就是从 32G binlog 的两头地位开始传输。 而后开始复制的 IO 线程，过十几秒，就能够看到复制报错： 查看 Error log： 和咱们想要复现的报错一样。 上面咱们来看一下原理： 这个复现中有几个因素： ...

作者：蒋乐兴MySQL DBA，善于 python 和 SQL，目前保护着 github 的两个开源我的项目：mysqltools 、dbmc 以及独立博客：https://www.sqlpy.com。本文起源：原创投稿*爱可生开源社区出品，原创内容未经受权不得随便应用，转载请分割小编并注明起源。概要之前有做过一个 binlog 压缩能节约多少空间的测试，成果上看还是比拟现实的，能够节约一半以上的空间。然而这个又引出了一个新的问题，那就是这个性能对性能有多大影响呢？于是我又在测试环境试了一下，测试环境的物理配置如下。 依据之前的教训这套测试环境在 120 个表 + 240 个并发的状况，能够获得一个性能上的极大值；所以在这里就间接应用这个作为测试压力。 8.0.19 场景第一步：装置。 dbma-cli-single-instance --port=3306 --max-mem=131072 \--pkg=mysql-8.0.19-linux-glibc2.12-x86_64.tar.xz install第二步：创立测试用户。 create user sysbench@'%' identified by 'sysbench';create database tempdb;grant all on tempdb.* to sysbench@'%';第三步：填充数据并进行压力测试。 sysbench --mysql-host=192.168.100.10 --mysql-port=3306 --mysql-user=sysbench \--mysql-password=sysbench --tables=120 --table_size=100000 --mysql-db=tempdb \--time=3600 --threads=240 oltp_point_select preparesysbench --mysql-host=192.168.100.10 --mysql-port=3306 --mysql-user=sysbench \--mysql-password=sysbench --tables=120 --table_size=100000 --mysql-db=tempdb \--time=3600 --threads=240 oltp_point_select run性能体现。 资源耗费状况。 8.0.20 + binlog 压缩第一步：装置。 ...

作者：戴骏贤网易游戏 技术部资深数据库系统工程师。本文起源：原创投稿*爱可生开源社区出品，原创内容未经受权不得随便应用，转载请分割小编并注明起源。1. 问题起源不久前用户反馈部门的 MySQL 数据库产生了数据更新失落。为了解决这个问题，过后对用户应用的场景进行了剖析。发现可能是因为用户在两台互为主从的机器上都进行了写入导致的数据失落。 如图所示，是失常和异常情况下利用写入数据库的示例。随后在更加深入调查问题的过程中，DBA 发现了故障引起数据失落的起因： 如图 1-2 所示为故障具体过程的还原。从图中能够看出在第 3 步 DP 上的写入操作，在复原 DA 到 DP 的同步之后，笼罩了第 4 步 DA 上的写入。因而导致了最终两台机器数据不统一，并且有一部分数据更新失落。 在这里置信读者都会有一个疑难， 在第 4 步之后数据变成了(id : 1 ,name : name4)，那么第 3 步操作的时候写入的语句是 update t20200709 set name = 'name3' where id =1 and name='name2'，在第 5 步复原同步的时候这条语句在 DA 上重放应该不会被胜利执行，毕竟 Where 条件都不匹配了。而且在 DP 产生的 Binlog 中，的确也记录了 SQL 语句的 Where 条件，无论从哪个角度上来看第 3 步的 SQL 语句都不应该被重放胜利。 ### UPDATE `test`.`t20200709`### WHERE### @1=1 /* INT meta=0 nullable=0 is_null=0 */### @2='name2' /* VARSTRING(255) meta=255 nullable=1 is_null=0 */### SET### @1=1 /* INT meta=0 nullable=0 is_null=0 */### @2='name3' /* VARSTRING(255) meta=255 nullable=1 is_null=0 */# at 684315240那么这个问题难道是 MySQL 本身的 Bug，抑或是 MySQL 在某些非凡参数或者条件下的失常体现？对于这个问题，本文将可能的给出这个问题的具体解释和剖析。 ...

作者：xuty本文起源：原创投稿*爱可生开源社区出品，原创内容未经受权不得随便应用，转载请分割小编并注明起源。很多时候，当咱们的业务数据产生了不失常的变动，但却无奈得悉这类操作是在哪里进行，并且如何进行，单单从程序当面排查很费劲。那么就须要通过剖析数据库日志来失去历史执行 SQL，依据 SQL 执行逻辑来确认代码地位，进而确认是否是 BUG，亦或是误操作等。一 、binlog 简介binlog 是 MySQL Server 层记录的二进制日志文件，用于记录 MySQL 的数据更新或者潜在更新（比方 DELETE 语句执行删除而理论并没有符合条件的数据），select 或 show 等不会批改数据的操作则不会记录在 binlog 中。通常在 binlog_format =  ROW 的环境下，咱们能够通过 binlog 获取历史的 SQL 执行记录，前提是必须开启 binlog_rows_query_log_events 参数（默认敞开，倡议开启），该参数能够通过rows_query_event 事件记录原始的 SQL，如果不开启的话，则只能获取 SQL 对应的行数据。 二、binlog 解析因为 binlog 是二进制文件，所以无奈间接应用文本关上，须要应用对应的解析工具才能够查看具体内容。2.1 show binlog events show binlog events 形式能够解析指定 binlog 日志，但不合适提取大量日志，速度很慢，不倡议应用。 2.2 mysqlbinlogmysqlbinlog 是 mysql 原生自带的 binlog 解析工具，速度快而且能够配合管道命令过滤数据，适宜解析大量 binlog 文件，倡议应用。因为 windows 上面无奈应用管道命令如此简洁的提取出 SQL，所以这边就只写 Linux 下的应用办法。我平时的做法会将 windows 上面的 binlog 拷贝到 Linux 下，再利用 Linux 的管道命令解析。集体罕用的 Linux 下解析命令：mysqlbinlog /data/mysql_data/bin.000008  --database EpointFrame  --base64-output=decode-rows -vv  --skip-gtids=true |grep  -C 1 -i "delete from  Audit_Orga_Specialtype" > /opt/sql.log ...