MySQL-记一次备份失败的排查过程

2022-08-30 11:58:20

山竹来临，窝在家里整理个人文档。

本篇文章主要讲解排查问题的思路，涉及linux 删除文件的原理、实例误删数据恢复、MySQL实例初始化参数优先级别等，虽然涉及知识点比较浅，但是个人觉得挺有意思的，所以翻出笔记发布出来。

如果转载，请注明博文来源： www.cnblogs.com/xinysu/ ，版权归博客园苏家小萝卜所有。望各位支持！

1 备份出错咯

测试环境测试 xtrabackup 相关性能的时候，备份失败！

备份指令如下：

 innobackupex --defaults-file=/apps/conf/mysql/mysql5_3306.cnf --socket=/tmp/mysql3306.sock --user=[*]--password=[*] --no-timestamp /apps/mysql_backup/test_backup_1 > /apps/mysql_backup/backup.log 2>&1

备份错误日志如下：

xtrabackup: The latest check point (for incremental): ''

xtrabackup: Stopping log copying thread.

.xtrabackup: warning: Log block checksum mismatch (block no  at lsn ):

expected , calculated checksum

xtrabackup: warning: this is possible when the log block has not been fully written by the server, will retry later.

 :: >> log scanned up to ()

 :: Executing UNLOCK TABLES

 :: All tables unlocked

 :: Backup created in directory '/apps/mysql_backup/test_backup_1/'

MySQL binlog position: filename 'mysql-bin.000001', position ''

 :: [] Writing /apps/mysql_backup/test_backup_1/backup-my.cnf

 :: []        ...done

 :: [] Writing /apps/mysql_backup/test_backup_1/xtrabackup_info

 :: []        ...done

xtrabackup: Transaction log of lsn () to () was copied.

xtrabackup: error: last checkpoint LSN (1209962) is larger than last copied LSN (1209856).

Tips：

数据库实例运行正常的情况，在各个log buffer中，会存有各个LSN，可以通过 show engine innodb status 查看，但是注意，这个lsn并非是直接从磁盘文件获取，而是从buffer 中获取。说明如下：

dba@localhost : (none) ::> show engine innodb status \G

......

---

LOG

---

Log sequence number

Log flushed up to

Pages flushed up to

Last checkpoint at

 pending log flushes,  pending chkp writes

 log i/o's done, 0.00 log i/o's/second

......

# Log sequence number: 当前系统最大的LSN号

# log flushed up to: 当前已经写入redo日志文件的LSN

# pages flushed up to：已经将更改写入脏页的lsn号

# Last checkpoint at：系统最后一次刷新buffer pool脏中页数据到磁盘的checkpoint

# LSN1 = Log sequence number
# LSN2 = log flushed up to
# LSN3 = pages flushed up to
# LSN4 = Last checkpoint at
# LSN1 >= LSN2 >= LSN3 >= LSN4

2 备份错误解读

xtrabackup: error: last checkpoint LSN (1209962) is larger than last copied LSN (1209856).

说明xtrabckup 同步 redo log 到完成的时候，自身的 redo log 最后的 lsn 跟当前数据库的 ib_logfile文件最后的 lsn对比，发现不匹配。

先检查备份失败实例内的 ib_logfile 文件：

正常 ib_logfile 文件的change time 应该是跟数据库的初始化时间一致，因为没有修改文件的权限，但是显示的change time 明显晚与实例的运行时间，怀疑是否这几个ib_logfile[*] 文件被覆盖！

为验证ib_logfile[*] 文件被覆盖，检查 mysql 进程下是否有 deleted 句柄，截图如下，发现 ib_logfile[*]文件确实被覆盖。

MySQL-记一次备份失败的排查过程

3 排查问题

哇，原来文件被删除，这里有几个疑问：

为何文件被删除，不影响3306 实例 mysqld 的运行，3306 仍支持正常的 dml及ddl操作？
306的redo log 是写入到哪些地方？
3306实例丢失的文件能否恢复，能否正常使用？
为何只有 redo log 文件被删除，是什么操作导致？

3.1 文件被删，实例为何能正常运行

在linux中，每个文件都有两个 link 计数器：

i_count：文件使用者或者被调用的数量，理解为内存引用的计数器。文件被进程打开使用的时候，自增+1。
i_nlink：硬链接的数量，理解为磁盘引用计数器。创建文件的硬链接的时候，自增+1。

当我们执行rm操作的时候，实际是 i_nlink-1，不一定真正删除文件，只有当 i_nlink=0 & i_count=0 时，文件才会被真正删除。案例中的 ib_logfile[*] 由于没有新创建硬链接，所以 i_nlink = 1，加上此时 3306实例处于运行中，需要调用到 ib_logfile[*]文件，所以 i_count = 1( 当前无其他进程使用到ib_logfile[*] )，当文件被删除的时候，i_nlink =0 但是 i_count=0，故文件不会被真正删除，仅删除 inode 连接，并没有删除磁盘的数据块。

那么被进程调用的文件，遭遇 rm 操作，那么它将何去何从呢？

首先，该文件的 i_nlink被删除，剩下 i_count，故仅删除磁盘硬链接，内容未删除。可以通过 proc 文件系统查找文件。每个进程都有进程id，可以通过 proc文件系统查找到该进程打开及调用的文件的链接。

测试1：在运行的新实例 3006 上，删除3个文件后检查

3.2 数据实际写入到哪里，原被覆盖文件？proc文件系统文件？

测试2：删除表格文件，查看句柄size是否变化？

测试内容：删除ib_logfile0文件及tbb.ibd文件，往 tbb 表格插入数据，查看 ib_logfile0大小及tbb.ibd大小

测试说明：为何是查看大小，而不是查看change time呢？因为node链接存储了文件的属性，删除了该链接，则无法查看文件属性，仅能通过lsof查看文件大小来判断写入情况。/proc文件系统中的 deleted 软连接，stat查看也是查看软连接的属性，并非真实文件数据块。无论是root还是其他用户删除，这个文件都能写入。

测试过程：见截图

测试结果：因为ib_logfile 是固定大小1G，无法查看到change时间，故不能验证；但是可以从 tbb.ibd 文件大小得知，实际是 redo log 是写入到被删除的文件的。

MySQL-记一次备份失败的排查过程

3.3 恢复被删除实例数据文件

若是主库文件被删
- 检查从库是否正常、是否无删除文件
  1. 从库正常
    1. 方案1
      1. 主从切换
      2. 旧主上，根据deleted句柄重定向被删除的数据块到原先的磁盘位置，例： cat /proc/16979/fd/36 > /apps/dbdat/mysql5_data3306/sophia/tba.ibd
    2. 方案 2
      1. 重做旧主库，重做后恢复从库使用
  2. 从库不正常，文件也被删
    1. 从库，停止复制
    2. 从库，根据deleted句柄重定向被删除的数据块到原先的磁盘位置，例： cat /proc/16979/fd/36 > /apps/dbdat/mysql5_data3306/sophia/tba.ibd
    3. 从库，恢复复制
    4. 检查从库追上主库
    5. 主从切换
    6. 旧主新从，停止复制，重定向文件内容或者重做从库
若是从库文件被删
1. 方案1
  1. 从库停止复制
  2. 从库上，根据deleted句柄重定向被删除的数据块到原先的磁盘位置，例： cat /proc/16979/fd/36 > /apps/dbdat/mysql5_data3306/sophia/tba.ibd
2. 方案2
  1. 重做旧主库，重做后恢复从库使用

3.4 为何仅ib_logfile[*]文件被删除，为何被删

查看 mysql 3306 的error 看看有啥苗头：

180912 15:09:51 [Note] Plugin 'FEDERATED' is disabled.

180912 15:09:51 InnoDB: The InnoDB memory heap is disabled

180912 15:09:51 InnoDB: Mutexes and rw_locks use GCC atomic builtins

180912 15:09:51 InnoDB: Compressed tables use zlib 1.2.3

180912 15:09:51 InnoDB: Using Linux native AIO

180912 15:09:51 InnoDB: Initializing buffer pool, size = 1.0G

180912 15:09:51 InnoDB: Completed initialization of buffer pool

InnoDB: The first specified data file /apps/dbdat/mysql5_data3306/ibdata1 did not exist:

InnoDB: a new database to be created!

180912 15:09:51  InnoDB: Setting file /apps/dbdat/mysql5_data3306/ibdata1 size to 1000 MB

InnoDB: Database physically writes the file full: wait...

InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000

180912 15:09:55  InnoDB: Log file /apps/dbdat/mysql5_data3306/ib_logfile0 did not exist: new to be created

InnoDB: Setting log file /apps/dbdat/mysql5_data3306/ib_logfile0 size to 1000 MB

InnoDB: Database physically writes the file full: wait...

InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000

180912 15:09:58  InnoDB: Log file /apps/dbdat/mysql5_data3306/ib_logfile1 did not exist: new to be created

InnoDB: Setting log file /apps/dbdat/mysql5_data3306/ib_logfile1 size to 1000 MB

InnoDB: Database physically writes the file full: wait...

InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000

180912 15:10:01  InnoDB: Log file /apps/dbdat/mysql5_data3306/ib_logfile2 did not exist: new to be created

InnoDB: Setting log file /apps/dbdat/mysql5_data3306/ib_logfile2 size to 1000 MB

看log，是新建实例的时候，覆盖了 3306实例的 ib_logfile跟ibdata1，但是实际上为何只有 ib_logfile被覆盖呢？查看历史操作命令，找到了初始化实例的指令如下：

history | grep mysql

368 /apps/svr/mysql57/bin/mysqld --initialize --datadir=/apps/dbdat/mysql57_data3307 --user=apps --innodb-data-file-path=ibdata1:1000M:autoextend --innodb-data-home-dir=/apps/dbdat/mysql57_data3307 --innodb-log-file-size=1000M --innodb-log-files-in-group=4

3.5 为何使用命令指定参数执行新建实例，会覆盖其他实例的的文件呢？

查看history 操作时，发现之前执行了了初始化实例的指令，没有指定配置文件，而是指定了 datadir，另起服务器，执行该命令，是正常，截图如下，那么这里又引申了第五个问题：为何使用命令执行新建实例，会覆盖其他实例的的文件呢？

灵机一动的我，联想到了配置文件的默认读取顺序，mysql安装的时候，读取配置文件的优先顺序：https://dev.mysql.com/doc/refman/5.7/en/option-files.html 。查看 /etc/my.cnf ，发现确实是有文件存在，并且这个文件是 3306的配置文件内容。

File Name	Purpose
/etc/my.cnf	m
/etc/mysql/my.cnf	Global options
SYSCONFDIR/my.cnf	Global options
$MYSQL_HOME/my.cnf	Server-specific options (server only)
defaults-extra-file	The file specified with --defaults-extra-file, if any
~/.my.cnf	User-specific options
~/.mylogin.cnf	User-specific login path options (clients only)

这个时候，可以初步确认，mysql 3307 初始化的时候，除了使用指定的指令外，其他需要的启动参数会从默认的配置文件路径依次读取。那么，mysql 初始化需要读取哪些必备参数呢？

mysql 5.7 ，无默认配置文件，仅指定参数 datadir basedir 初始化后生成 :mysql\sys\performance_schema 3个数据库目录及表格文件，同时生成 ibdata1、ib_logfile[*]等文件，是否可以判断，初始化过程中，需要指定跟 ibdata1、ib_logfile【*】相关参数、error log位置、user 则正常呢？

/apps/svr/mysql57/bin/mysqld --initialize --datadir=/apps/dbdat/mysql57_data3307 --user=apps --innodb-data-file-path=ibdata1:1000M:autoextend --innodb-data-home-dir=/apps/dbdat/mysql57_data3307 --innodb-log-file-size=1000M --innodb-log-files-in-group=4 --basedir=/apps/svr/mysql57 --innodb_log_group_home_dir=/apps/dbdat/mysql57_data3307 --innodb-log-files-in-group=4 --log-error=/apps/logs/mysql/error3307.log

你以为这样，就可以安装了吗？

并不，当存在默认路径的配置文件时，除了指定参数外，还是会去读默认路径上的配置文件为主。

TIPS：

模拟的过程中，一直无法重现这个错误，最后发现，没有覆盖文件，是因为：当配置文件的权限为所有人可写的情况下，mysql担心该配置文件被恶意修改，故会忽略该文件，不读该文件配置。

mysqld: [Warning] World-writable config file '/etc/my.cnf' is ignored.

4 错误原因总结

综上分析，则可以确定 3306实例正常运行期间，某位小伙伴使用指令初始化 3307实例，由于未指定 innodb_log_group_home_dir，mysql引擎去默认路径下查找配置文件，恰巧 /etc/my.cnf 是 3306实例的配置文件，故 3307实例初始化的 innodb_log_group_home_dir 指向了 3306 实例，覆盖了 3306 实例的 ib_logfile[*] 文件。

那为何xtrabackup为何会报错 xtrabackup: error: last checkpoint LSN (1209962) is larger than last copied LSN (1209856)？

这是因为 3307 实例初始化的过程中，读取 /etc/my.cnf 配置文件的时候，5.7版本已经没有innodb_additional_mem_pool_size参数，故初始化到这里的时候，报错

2018-09-12T07:26:06.003983Z 0 [ERROR] unknown variable 'innodb_additional_mem_pool_size=32m'

2018-09-12T07:26:06.004004Z 0 [ERROR] Aborting

2018-09-12T07:26:06.004192Z 0 [Note] Binlog end

2018-09-12T07:26:06.010705Z 0 [Note] InnoDB: FTS optimize thread exiting.

2018-09-12T07:26:06.010917Z 0 [Note] InnoDB: Starting shutdown...

2018-09-12T07:26:06.111107Z 0 [Note] InnoDB: Dumping buffer pool(s) to /apps/dbdat/mysql57_data3307/ib_buffer_pool

2018-09-12T07:26:06.111312Z 0 [Note] InnoDB: Buffer pool(s) dump completed at 180912 15:26:06

2018-09-12T07:26:07.849696Z 0 [Note] InnoDB: Shutdown completed; log sequence number 1209962

2018-09-12T07:26:07.849933Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"

实际上，如果是 5.7实例读取 5.7配置文件去覆盖 5.7的旧实例，实际上备份并不会报错，并且备份文件在还原使用的时候也无异常，但是有一个致命的问题，则是备份过程中无法感知实例的redo log变化，故并无跟进整个实例的redo log，导致备份生成的xtrabckup_binlog_info 文件中的binlog + postion 位置点是错误的，如果使用该备份来做从库，则会出现严重缺失数据！！

新服务器上做测试如下：

初始化 5.7版本的3306实例，生成一张大表
拷贝 5.7 3306 实例的配置文件到 /etc/my.cnf
指定参数初始化 3307实例
确认 3306 实例的 ib_logfile 被覆盖，但 3306 实例可以正常执行操作
备份 3306 实例正常，执行备份期间无错误
备份 3306实例期间，等待其拷贝完某张空表 tb.ibd 文件后，迅速 insert 这张表 5000 行数据
进行还原操作，验证备份是否有效
1. 检查 tb.ibd 文件大小为几十kb
2. 检查备份文件夹中的 xtrabackup_logfile , 该文件仅为 2.5k，并未记录 insert tb.ibd文件的操作
3. apply log 后启动文件，发现tb.ibd 仍然为空表
结论
1. 同版本覆盖的情况下
2. 备份还原均无报错信息，但是其实是无效的，但是备份的 xtrabackup_binlog_info 记录的log 、pos 与实际不相符
3. 因为在做数据操作的时候，ib_logfile 没有变动，故xtrabackup_logfile 文件，并没有记录到实际的redo log，所以其 xtrabackup_binlog_info 记录的log 跟pos 与实际不相符

5 处理流程总结

备份失败
1. 失败原因：ib_logfile被覆盖
引发问题
1. 运行中的db实例，文件被覆盖，为何可正常运行？
  - linux 删除文件原理，rm 被进程使用的文件，仅删除 i_nlink，未删除实际数据块，可从proc文件系统查找
2. 当文件被覆盖后，还会继续写入进程的修改数据吗？
  - 写入到 proc 指向的数据块中，正常读写
3. 如何恢复被覆盖的文件？
  - 确保无数据写入proc 指向的 deleted文件，cat 重定向（注意耗时）
查找文件被覆盖的原因
- 引发问题
  1. 为何只有 ib_logfile[*]被覆盖？
    1. 初始化仅指定部分参数，指定参数优先级别最高，其他读取默认配置文件参数，因为指定了 innodb-data-file-path、datadir，没有指定 innodb_log_group_home_dir，故仅覆盖 ib_logfile[*]
  2. mysql初始化指定参数跟默认路径配置文件的优先级？
    1. 优先级别高低
      1. 用户指定参数
      2. 默认路径配置文件参数，按照默认路径排序，属性是 global 的，靠前的优先级别底，越后越高
      3. mysqld 默认参数值
  3. 为何某些情况下配置了/etc/my.cnf，但是不读取？
    1. 当配置文件的权限为所有人可写的情况下，mysql担心该配置文件被恶意修改，故会忽略该文件，不读该文件配置
    2. mysqld: [Warning] World-writable config file '/etc/my.cnf' is ignored.
    3. 注意查看配置文件权限不是 777 权限

6 思考与改进

关于部署，使用defaults-file指定部署

关于恢复，注意主从处理及readonly 处理，确保cat 重定向的过程中，proc文件系统被删除的文件无写入

关于监控，线上应当添加对相关data目录的 proc deleted句柄的相关监控

码农公寓

1 备份出错咯

2 备份错误解读

3 排查问题

3.1 文件被删，实例为何能正常运行

3.2 数据实际写入到哪里，原被覆盖文件？proc文件系统文件？

3.3 恢复被删除实例数据文件

3.4 为何仅ib_logfile[*]文件被删除，为何被删

3.5 为何使用命令指定参数执行新建实例，会覆盖其他实例的的文件呢？

4 错误原因总结

5 处理流程总结

6 思考与改进

相关文章