ARTICLE · INTELLIGENCE

战地情报 · 详情页

来自尧图项目组的一线实战观察与深度解析

MySQL binlog日志查看与数据恢复实战指南

MySQL binlog日志查看与数据恢复实战指南

最近在给一个内部项目做数据核对的时候,发现某张业务表的几条记录对不上,排查到最后指向了MySQL的binlog日志。当时我顺手查了一下团队的提问记录,发现大家对“mysql查看binlog日志”这件事的认知其实挺分裂的:有人觉得它难,有人觉得它简单,还有人压根不知道binlog到底记录了什么。这篇文章不准备讲太深的理论,就把我实际查过、恢复过、踩过坑的经验整理出来,给你一条能照着操作的完整路径。

能解决什么问题?一句话:当你想知道某个时间段数据库里到底执行了什么、某个数据是什么时候变的、或者某条数据误删之后能不能找回来,都得靠binlog。适合谁看?刚接触MySQL不久、被二进制日志搞得一头雾水的开发或运维;也适合那种已经会show master status,但一碰到实际排查就卡壳的人。

想了想,还是先从“binlog到底长什么样”说起。不把这个底层概念理顺,后面所有命令都是背式子,换个场景就忘了。

1. 先搞清楚binlog到底是个什么东西再动手查

1.1 我一开始的理解是错的

我第一次用binlog的时候犯过一个特别基础的错误:以为binlog就是一张可以随便SELECT的表。当时我想查一条历史UPDATE,想了半天去哪张表里看,后来才意识到binlog根本不在InnoDB的表空间里,而是MySQL Server层维护的一批二进制文件,默认放在数据目录下,文件名类似mysql-bin.000001、mysql-bin.000002这种递增编号。

binlog里记录的也不是“某行数据现在长什么样”,而是“数据库发生过的变更操作”。它对INSERT、UPDATE、DELETE这类写操作做记录,对SELECT这种读操作不记录。这一点很重要,因为很多同事问我“能不能查一下某张表被查了多少次”——查不了,那不是binlog的职责范围,该去看general log和慢查询日志。

1.2 binlog和常搞混的redo log不是一回事

还有一个高频混淆点:redo log和binlog。我之前也分不清,后来用一个生活化的类比才彻底理清。redo log是InnoDB存储引擎自己的“草稿本”,主要用于崩溃恢复,比如你写到一半机器断电了,重启后靠redo log把没写完的数据补上。binlog则是MySQL Server层的“流水账”,主要用于数据复制和数据恢复,比如从库同步主库、误删数据后回放历史操作。

简单点说:redo log是物理级别的,记录的是“哪个数据页被修改了”;binlog是逻辑级别的,记录的是“执行过什么操作”。日常排查数据变更问题,我们基本只看binlog。搞清楚这个区别之后,再去看各种查询命令,思路会顺很多。

1.3 怎么看binlog当前有没有在写、写到了哪个文件

查binlog之前,先确认一件事:这台MySQL到底开没开binlog。我见过不少环境,业务跑得好好的,到出问题想查日志的时候才发现log_bin根本没打开,只能干瞪眼。检查命令很简单:

SHOW VARIABLES LIKE 'log_bin'; SHOW BINARY LOGS;

如果log_bin是ON,SHOW BINARY LOGS会列出当前所有binlog文件,包括文件名、文件大小,还有一个我后面会专门聊的加密字段。如果想看当前正在写哪个文件、写到了什么位置,用:

SHOW MASTER STATUS;

结果里的File列就是当前正在用的binlog文件,Position表示下一个写入位置的偏移量。这两个信息在后面的按位置恢复里会变成非常重要的锚点。我习惯把这些输出先截下来留存,排查问题时能省不少时间。

现在你已经知道binlog是文件了,接下来最直观的问题就是:怎么把文件里的内容读出来?我先说个结论:别用cat,也别用vim,打开全是乱码。至于为什么,下一节来说。

2. 为什么直接打开binlog全是乱码:正确的查看姿势

2.1 二进制日志的“二进制”三个字是什么意思

binlog文件不是纯文本文件,里面是MySQL自己定义的一套二进制事件格式。每个事件都有固定的头部信息,记录了事件类型、执行时间、所属server_id、结束位置等元数据,接着才是真正的事件体数据。正因为有这些二进制的头信息和事件体,你用cat打开的时候才会看到一堆带特殊字符的乱码,偶尔还会夹杂几个能看懂的英文字段名,让人误以为文件损坏了。

实际上文件没坏,只是没找对工具。这就好比一份压缩包,你直接双击进去看到的是文件名列表,但想完整还原文件内容,必须用解压工具。binlog的“解压工具”就是MySQL自带的命令行程序mysqlbinlog。

2.2 用mysqlbinlog做第一次成功解析

假设当前最新的binlog文件叫mysql-bin.000003,最简单的解析命令是:

mysqlbinlog /var/lib/mysql/mysql-bin.000003

直接执行会把解析出来的SQL事件打印到终端。文件比较大时别这么干,建议先重定向到文件再慢慢看:

mysqlbinlog /var/lib/mysql/mysql-bin.000003 > /tmp/binlog_003.sql

如果文件里涉及ROW格式的记录,直接解析出来的内容会是一堆base64编码的字符串,需要一个关键参数配合:

mysqlbinlog -v --base64-output=DECODE-ROWS /var/lib/mysql/mysql-bin.000003

这里的-v表示输出注释形式的伪SQL语句,--base64-output=DECODE-ROWS会把ROW格式事件里的base64数据解码成可读的“字段名=值”形式。这两兄弟在实际排查里几乎是固定搭配,建议直接记成肌肉记忆。

2.3 解析结果里每一行是什么意思

解析出来之后,我们能看到一大片这样的内容:

# at 154 #230918 10:23:45 server id 1 end_log_pos 219 Query thread_id=8 exec_time=0 error_code=0 SET TIMESTAMP=1695018225/*!*/; BEGIN /*!*/; # at 219 #230918 10:23:45 server id 1 end_log_pos 378 Query thread_id=8 exec_time=0 error_code=0 use `test_db`/*!*/; SET TIMESTAMP=1695018225/*!*/; UPDATE test_table SET status = 'paid' WHERE id = 1001 /*!*/; COMMIT/*!*/;

我来说几个初学者容易忽略的点:

  • # at 154表示这条事件在binlog文件中的起始偏移量,也就是position;
  • end_log_pos 219表示事件结束后,下一条事件的起始位置。在恢复数据时,我们经常要拿这两个position做区间;
  • server id 1是产生这条日志的服务器标识,多主多从环境里排查“这条操作到底是谁写的”就靠它;
  • usetest_db``表示这条SQL是在哪个库上执行的,等会儿按库过滤时会发现它很重要。

看到这些字段,基本上就能还原出当时的执行轨迹了。我第一次把这些内容完整读下来的时候,有种“历史的每一个瞬间都在眼前重放”的感觉,后面排查问题也确实靠它救了几次场。

基础知识铺垫得差不多了,下面进入正题:实际工作里,我们到底有哪些高频需求,分别怎么查。

3. 工作中遇到最多的三种捞取日志需求

3.1 按时间范围捞日志:先猜时间,再压缩范围

最常见的场景:业务方反馈“昨天下午XX点有一批数据不对,帮我看看那个时间段执行了什么”。这时候我一般不会直接解析整个binlog文件,而是用时间参数做过滤:

mysqlbinlog --no-defaults \ --start-datetime="2024-01-15 14:00:00" \ --stop-datetime="2024-01-15 14:30:00" \ /var/lib/mysql/mysql-bin.000003

两个时间参数都是可选的。只想看14点之后的,就只写--start-datetime;只想看14点半之前的,就只写--stop-datetime。有个细节要注意:这里的时间是MySQL会话时区下的执行时间,如果你的服务器时区和业务方说的“昨天下午”对不上,查出来的内容可能会有偏差。遇到过不少次,业务说下午2点,日志显示下午4点,结果发现是时区没对齐。

另外一个建议:不要一开始就把时间范围拉得太宽。我先用--start-datetime粗略圈一段,看结果,再逐步收窄。binlog解析是IO密集操作,范围越小越省时间。我们某个库曾经一天产生8GB的binlog,全量解析一次要跑四十分钟,用时间过滤缩到十分钟后,体验完全不一样。

3.2 按position定位恢复:从指定偏移量开始回放

第二种场景适合“我已经知道问题大概出在哪个位置”的情况。比如前面用SHOW MASTER STATUS查到了当前position是4382,现在希望把这个位置之后的日志全部回放出来,可以用:

mysqlbinlog --no-defaults \ --start-position=4382 \ /var/lib/mysql/mysql-bin.000003

如果还知道问题结束的位置,可以加上--stop-position做区间限制。在恢复数据时,这个操作几乎是必用的。我举个例子:某天发现一张表的数据被批量UPDATE错了,幸运的是事故发生在凌晨4点,我们事先知道4点之前有完整备份,备份之后到出错之间的binlog还在。这时候恢复方案是:先把备份恢复到临时实例,再用--start-position从备份完成时的position开始回放,一直回放到出错前一刻的position,最后把正确数据导出来。

这里的核心思路是:binlog里的position是连续的,相当于给数据库的历史操作做了一个无限细的刻度。我们不需要乱猜,只要找到两个刻度,就能精确取出中间那一段操作。

3.3 只要某张表的操作:row格式下怎么过滤

第三类高频需求是“只看某张表的操作”。这个要分两种情况说。

如果binlog_format是STATEMENT或MIXED,日志里记录的是SQL原文,那么解析出来后直接grep表名基本就能定位:

mysqlbinlog /var/lib/mysql/mysql-bin.000003 | grep "test_table"

如果binlog_format是ROW,情况会稍微复杂。ROW格式下记录的不是SQL原文,而是“哪一行发生了变更,变更前后各是什么值”,工具会用伪SQL的形式把它展示出来,但SQL里不一定带表名。不过mysqlbinlog还是给我们留了一个按库过滤的参数:

mysqlbinlog --no-defaults \ --database=test_db \ --base64-output=DECODE-ROWS -v \ /var/lib/mysql/mysql-bin.000003

--database表示只解析指定库的变更。它本质上是通过binlog事件里记录的库上下文来做过滤,所以结构是“按库过滤”,并没有特别干净的“按表过滤”参数。实际操作里,我常用的组合是先按库过滤,再把输出存成文件,然后在文件里搜索表名和字段名:

mysqlbinlog --no-defaults --database=test_db --base64-output=DECODE-ROWS -v \ /var/lib/mysql/mysql-bin.000003 > /tmp/only_test_db.sql grep -n "test_table" /tmp/only_test_db.sql

有人会觉得这样不够“优雅”,但在生产环境里它就是简单可靠,比去折腾各种解析脚本要稳得多。

3.4 带base64-decode看row里的实际数据

ROW格式还有一个让很多人头疼的地方:如果不带--base64-output=DECODE-ROWS,看到的内容长这样:

### UPDATE `test_db`.`test_table` ### WHERE ### @1='1001' ### @2='pending' ### SET ### @1='1001' ### @2='paid'

我自己第一次看到这种@1、@2的格式是一脸懵的。这里解释一下:@1对应表的第一列,@2对应第二列,以此类推。WHERE部分记录的是变更前该行用于定位的旧值,SET部分记录的是变更后的新值。

如果你想知道某个字段到底从什么值变成了什么值,这其实是最好懂的格式。比如上面这段,意思就是:id=1001这一行,第二列从'pending'变成了'paid'。在很多数据核查场景里,这种“前后对比”恰恰是我们需要的核心信息。

有一点要注意:binlog里某一列具体显示成什么样的可读格式,受表的元数据影响。如果你发现某个字段显示成十六进制、时间戳数字之类,别慌,先确认一下字段类型,再判断需不需要转换。常见的0000开头字段往往对应binary/varbinary类型。

前面说的都是“拿到日志之后怎么读”,但还有个前置问题容易被忽略:你真的读得全吗?binlog能不能记录完整、按什么格式记录,由一组参数说了算。这一节我把最容易影响查看结果的几个参数串一遍。

4. 想顺利查看binlog,先把这组前置参数和权限理顺

4.1 查别人日志前先确认自己有权限

binlog的读取有两个层面。如果你的账号是普通业务账号,想执行SHOW BINARY LOGS或SHOW BINLOG EVENTS,需要有REPLICATION SLAVE或REPLICATION CLIENT权限。实际在排查中,很多开发者用的是自己连业务库的账号,权限不够,一执行就报Access denied,这时候不要觉得是命令写错了,先检查授权。

SHOW GRANTS FOR 'your_user'@'%';

如果确实缺权限,需要找DBA给账号加上:

GRANT REPLICATION SLAVE, REPLICATION CLIENT ON *.* TO 'your_user'@'%';

另一个层面是直接读取binlog文件。如果你在服务器上执行mysqlbinlog命令,那么操作系统层面要对数据目录和binlog文件有读权限。有些团队把binlog放在专门的目录并做了权限隔离,普通登录账号一跑mysqlbinlog就Permission denied,这也是权限问题,不是工具问题。

4.2 log_bin、binlog_format和row_image:参数直接决定你能看到什么

查看binlog这件事能不能做、做出来是什么样子,很大程度上由三个参数决定。

第一个是log_bin,它决定binlog是否开启。我之前遇到过最遗憾的场景:新项目上线时忘了在配置里打开binlog,数据出了大问题才发现没有历史日志可用,那场排查基本等于盲人摸象。

第二个是binlog_format,它有STATEMENT、ROW、MIXED三种值。在MySQL 5.7.7及以上版本,默认是ROW。ROW格式记录的是每一行的实际变更,信息最全,恢复和核查最靠谱;STATEMENT格式记录的是SQL语句本身,文件小,但在某些场景下无法精确还原数据;MIXED则是混合策略。做数据核查的人,我强烈建议把格式固定成ROW,别为了省一点磁盘空间牺牲可观测性。

第三个是binlog_row_image,它有FULL、MINIMAL、NOBLOB三种取值,默认是FULL。这个参数影响ROW格式下到底记录哪些列。FULL会记录所有列的前后值,排查效果最好;MINIMAL只记录能定位到行的最小列集,文件小但信息少。排查问题时如果发现“为什么SET部分只有几个字段,其他字段哪去了”,先去查这个参数。

实际调整时,这些参数需要改配置文件并重启,或者用SET GLOBAL在线修改。在线修改binlog_format这类参数只对后续会话生效,历史日志不会变。所以排查历史问题的时候,看到的格式由当时写入时的配置决定,不能只看当前值。

4.3 日志保留时间设置错了,想查的时候啥都没有

这是我踩过最深的一个坑。曾经有一个客户环境,binlog保留时间被设成1小时,结果第二天早上业务反馈凌晨有数据被误改,我去服务器一看,对应的binlog已经因为过期被自动清理了。后来反复复盘,发现这类问题很少是因为“没开binlog”,更多是因为“开了,但保留时间太短”。

MySQL 8.0里,控制binlog过期的是binlog_expire_logs_seconds,默认值是2592000,也就是30天。MySQL 5.7及更早版本里常见的是expire_logs_days。排查前可以先确认一下:

SHOW VARIABLES LIKE 'binlog_expire_logs_seconds'; SHOW VARIABLES LIKE 'expire_logs_days';

如果你的环境希望“发生问题后至少能往前查3天”,那保留时间至少设成3天,最好再留点冗余,比如7天。磁盘充足的情况下,我一般建议保留不低于7天,因为binlog的价值不只是在排查事故,还可以用于增量备份和从库追赶数据,设太短会把后路堵死。

手动清理binlog也不是没有,但要特别小心。PURGE BINARY LOGS TO 'mysql-bin.000010';会删除该文件之前的所有binlog;PURGE BINARY LOGS BEFORE '2024-01-01 00:00:00';按时间删。这种操作在没确认备份完整之前千万不要乱执行,删掉了就等于把那段时间的可追溯性彻底抹掉了。我见过有人手滑把唯一的日志源删了,最后只能寄希望于冷备,那种窘境不想再经历第二次。

前面讲的都是“怎么查、查什么、前置条件是什么”,接下来我用一个真实发生过的小事故,把整个排查到恢复的流程完整走一遍。这个案例我已经脱敏处理,数据和表名都换过,但排查路径是原汁原味的。

5. 一次误删数据场景下的binlog回放全记录

5.1 事故现场和第一反应

某天上午11点左右,某内部系统的某个表突然有大量数据“消失”。组织方反馈得很急:“订单表少了一大片记录,客户那边已经在催了。”我当时的第一反应不是急着去翻binlog,而是先做三件事:

  1. 确认当前binlog是否打开;
  2. 确认从什么时间点开始异常;
  3. 确认是否存在可用的全量备份。

这三件事的顺序很重要。如果binlog没开,后面所有计划都要换成“找备份+人工补录”;如果备份时间点不清晰,后面回放的起点就不确定;如果异常时间都说不清,解析日志就无从下手。万幸的是,这台MySQL的binlog保留时间是7天,业务方判断异常发生在当天上午9点到10点半之间,前一天夜里有一条全量备份。

5.2 定位问题事件的具体位置

我先登录数据库查当前日志文件位置,同时把binlog文件列表拉出来:

SHOW BINARY LOGS; SHOW MASTER STATUS;

输出显示当前binlog文件是mysql-bin.000017。由于备份是凌晨做的,理论上备份之后到出问题前的所有操作都记录在mysql-bin.000017里。接下来我先把9点到10点半的日志导出来:

mysqlbinlog --no-defaults \ --start-datetime="2025-03-10 09:00:00" \ --stop-datetime="2025-03-10 10:30:00" \ -v --base64-output=DECODE-ROWS \ /var/lib/mysql/mysql-bin.000017 > /tmp/crash_range.sql

导出后先看文件大小和事件总数,确认区间没有明显异常。然后我在文件里搜索那张订单表的表名。因为binlog_format是ROW,导出的伪SQL里会出现类似### DELETE FROMorder_db.t_order``这样的内容;再配合前后的# at位置,我很快就锁定了问题事件段。

这里有个小技巧:先看# at位置和end_log_pos,再把中间这一段单独解析出来。比如我锁定了从# at 15400到end_log_pos 16820这一段是批量DELETE,那就用更精确的位置重新导出:

mysqlbinlog --no-defaults \ --start-position=15400 \ --stop-position=16820 \ -v --base64-output=DECODE-ROWS \ /var/lib/mysql/mysql-bin.000017

不需要再靠时间慢慢筛,直接看这一小段里到底删了哪些记录。当时我数了一下被删除的记录条数,和业务方反馈的“少了一大批”完全对得上。到此为止,问题原因基本定位:存在一次没带条件或条件过于宽泛的DELETE操作。

5.3 用binlog回放把数据救回来

定位到问题之后,恢复方案就很清晰了。这里有个原则要先讲:我们不会把凌晨备份到出错前的所有binlog一股脑回放到生产库,因为那会把9点到10点半之间的其他正常操作也再执行一遍,很可能产生冲突。正确的做法是:

  1. 先把凌晨的全量备份恢复到一台临时实例;
  2. 在临时实例上,从备份完成时的position开始回放binlog,回放到误删操作开始前的position为止;
  3. 把临时实例里恢复出来的正确数据导出;
  4. 把数据补回生产库。

备份完成时的position怎么找?有几种方式。如果你用的备份工具支持记录binlog position,比如mysqldump加上--master-data=2,备份文件的头部会直接写着当时的位置信息。我当时拿到了这样一行注释:

-- CHANGE MASTER TO MASTER_LOG_FILE='mysql-bin.000016', MASTER_LOG_POS=4382;

这行注释就是关键。意味着备份完成时,binlog正处于mysql-bin.000016的4382位置。所以在临时实例恢复备份后,应该从mysql-bin.000016的position 4382开始回放,直到误删事件开始前的位置。命令大致是:

mysqlbinlog --no-defaults \ --start-position=4382 \ --stop-position=15400 \ /var/lib/mysql/mysql-bin.000016 \ /var/lib/mysql/mysql-bin.000017 > /tmp/replay.sql

注意,这里我把两个文件都写进去了。mysqlbinlog支持一次传入多个文件,它会按顺序依次解析,非常适合这种跨文件回放场景。执行之前,我习惯先打开/tmp/replay.sql扫一眼,确认里面没有意外操作,然后再导入临时实例:

mysql -uroot -p < /tmp/replay.sql

回放完成后,在临时实例里查询目标表,发现9点到10点半之间被误删的数据确实都回来了,同时还保留着其他正常事务的更新结果。后续我就把这一小份结果导出成INSERT语句,交还给业务方核对后补回生产库。整个过程中生产库没有被打断,这也是binlog回放比直接在生产库回放要安全得多的原因。

5.4 这次回放暴露的几个隐藏坑

上面这套流程看着顺畅,其实我在操作过程中踩了几个坑,值得单拎出来说。

第一个坑:从备份位置到误删位置的区间里,存在跨binlog文件的边界。如果只看mysql-bin.000017,结果回放时发现最早的事件位置根本对不上,因为备份完成时的日志在mysql-bin.000016。解决方式就是上面提到的,把两个文件同时传给mysqlbinlog,并用--start-position和--stop-position精确限制。

第二个坑:导出文件时如果带着GTID环境,回放时经常会遇到一个问题——临时实例已经执行过某些事务,再回放相同GTID的事务会被跳过或报错。解决办法是在回放前清一下临时实例的gtid_executed,或者用--skip-gtids参数让mysqlbinlog忽略原GTID信息,在临时实例上产生新的事务标识。我当时的处理是加参数:

mysqlbinlog --skip-gtids --no-defaults \ --start-position=4382 --stop-position=15400 \ /var/lib/mysql/mysql-bin.000016 /var/lib/mysql/mysql-bin.000017 > /tmp/replay.sql

第三个坑:大事务会拖垮临时实例。binlog里记录的是提交后的事务,但一个事务可能包含几万行变更,回放时需要大量的临时空间和undo。如果临时实例规格太小,最好分批回放,或者至少预留足够的磁盘。我那次回放的是一个中等规模事务,临时实例差点把磁盘写满,后来加大磁盘才顺利完成。

第四个坑容易被忽略:误删之后如果线上又有新的写入,回放区间一定要精确到“误删操作开始前”。否则回放到误删之后的binlog,会把新的正确数据也覆盖掉。这也是为什么我一直强调position比时间更精确——时间会有时区误差和边界问题,position则是文件里的绝对坐标。

一次完整的回放下来,我对binlog的敬畏又多了几分。它就像一个沉默的记事本,只要你打开了它、设置对了参数、保留够了时间,它在关键时刻就能把丢失的数据原原本本地还给你。

6. 收尾之前,给我自己常用的几段命令做个小结

6.1 速查表式的心智模型

靠脑子一次性记住那么多参数不太现实,我整理了一个很小的速查维度,方便你保存在手边:

需求首选命令/参数一句话提醒
查看当前写日志状态SHOW MASTER STATUS; SHOW BINARY LOGS;确认有权限再执行
按时间段解析--start-datetime/--stop-datetime注意时区对齐
按位置解析--start-position/--stop-position备份里找恢复锚点
看ROW格式伪SQL-v --base64-output=DECODE-ROWS不要漏掉两个参数一起用
按库过滤--database=库名没有现成的按表过滤参数
跨文件回放mysqlbinlog 文件A 文件B位置区间跨越文件时用
GTID环境回放--skip-gtids防止事务被跳过或冲突
检查保留时间SHOW VARIABLES LIKE 'binlog_expire_logs_seconds'保留太短等于没日志

6.2 最后再分享两个我自己的习惯

我个人的经验是,与其把一堆命令背下来,不如先养成两个底层习惯。

第一个习惯:任何重要变更操作(备份、迁移、大事务)前,先记录一下当前的binlog文件名和position。这就像写日记之前先记一下页码,将来无论排查还是恢复,都有一条清晰的起点线。我有时候会在变更脚本最上面加一行注释,把当时的SHOW MASTER STATUS结果写进去,一个月后回头看,省了大把定位时间。

第二个习惯:每次解析binlog之后,输出文件一定要带时间戳命名,比如binlog_replay_20250310.sql。这看起来是小事,但在事故高峰期,你很可能同时导出七八份文件,命名混乱的那一刻真的会让人当场崩溃。命名规范了,排除过程才会顺手。

在做数据这条路上,“mysql查看binlog日志”这个技能看起来很基础,但用好了它就是数据库的一台时间机器。希望这一篇能帮你把概念、命令和场景串起来,下次真正遇到问题时,你能从容地打开那个文件,顺着位置和时间,把真相找回来。

RELATED READING

延伸阅读

更多一线实战笔记与深度复盘,助您持续精进