• 欢迎访问DBA的辛酸事儿,推荐使用最新版火狐浏览器和Chrome浏览器访问本网站
  • 欢迎大家关注博主公众号:DBA的辛酸事儿
  • 博文中若有错误的地方,请大家指正,大家的指正是我前进的动力

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

MySQL SEian.G 来源:苏家小萝卜 2年前 (2019-04-14) 784次浏览 已收录 0个评论
文章目录[隐藏]

一、备份出错

测试环境测试 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): '1209962'
xtrabackup: Stopping log copying thread.
.xtrabackup: warning: Log block checksum mismatch (block no 2364 at lsn 1209856):
expected 1161267116, calculated checksum 1312610971
xtrabackup: warning: this is possible when the log block has not been fully written by the server, will retry later.
180912 15:30:11 >> log scanned up to (1209856)
 
180912 15:30:11 Executing UNLOCK TABLES
180912 15:30:11 All tables unlocked
180912 15:30:11 Backup created in directory '/apps/mysql_backup/test_backup_1/'
MySQL binlog position: filename 'mysql-bin.000001', position '26708128'
180912 15:30:11 [00] Writing /apps/mysql_backup/test_backup_1/backup-my.cnf
180912 15:30:11 [00]        ...done
180912 15:30:11 [00] Writing /apps/mysql_backup/test_backup_1/xtrabackup_info
180912 15:30:11 [00]        ...done
xtrabackup: Transaction log of lsn (1209962) to (1209856) 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) 17:00:21> show engine innodb status \G
......
---
LOG
---
Log sequence number 4158179984
Log flushed up to   4158179984
Pages flushed up to 4158179984
Last checkpoint at  4158179975
0 pending log flushes, 0 pending chkp writes
128445 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

二、备份错误解读

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

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

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

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

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

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

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

三、排查问题

哇,原来 文件被删除,这里有几个疑问 :

1、为何文件被删除,不影响3306 实例 mysqld 的运行,3306 仍支持正常的 dml及ddl操作?

2、3306的redo log 是写入到哪些地方?

3、3306实例丢失的文件能否恢复,能否正常使用?

4、为何 只有 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个文件后检查

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

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

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备份失败的排查过程

灵机一动的我,联想到了配置文件的默认读取顺序,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.

四、错误原因总结

综上分析,则可以确定 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 位置点是错误的,如果使用该备份来做从库,则会出现严重缺失数据!!

新服务器上做测试如下:

1、初始化 5.7版本的3306实例,生成一张大表

2、拷贝 5.7 3306 实例的配置文件到 /etc/my.cnf

3、指定参数初始化 3307实例

4、确认 3306 实例的 ib_logfile 被覆盖,但 3306 实例可以正常执行操作

5、备份 3306 实例正常,执行备份期间无错误

6、备份 3306实例期间,等待其拷贝完某张空表 tb.ibd 文件后,迅速 insert 这张表 5000 行数据

7、进行还原操作,验证备份是否有效

(1)检查 tb.ibd 文件大小 为几十kb

(2)检查 备份文件夹中的 xtrabackup_logfile , 该文件仅为 2.5k,并未记录 insert tb.ibd文件的操作

(3)apply log 后启动文件,发现tb.ibd 仍然为空表

8、结论

(1)同版本覆盖的情况下

(2)备份还原均无报错信息,但是其实是无效的,但是备份的 xtrabackup_binlog_info 记录的log 、pos 与实际不相符

(3)因为在做数据操作的时候,ib_logfile 没有变动,故xtrabackup_logfile 文件,并没有记录到实际的redo log,所以其 xtrabackup_binlog_info 记录的log 跟pos 与实际不相符

五、处理流程总结

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

六、思考与改进

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

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

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

文章链接:

https://www.cnblogs.com/xinysu/p/9655759.html#autoid-3-4-0

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


如果您觉得本站对你有帮助,那么可以收藏和推荐本站,帮助本站更好地发展,在此谢过各位网友的支持。
转载请注明原文链接:记一次MYSQL备份失败的排查过程
喜欢 (2)
SEian.G
关于作者:
用心去记录工作,用心去感受生活,用心去学着成长;座右铭:苦练七十二变,笑对八十一难
发表我的评论
取消评论

表情 贴图 加粗 删除线 居中 斜体 签到

Hi,您需要填写昵称和邮箱!

  • 昵称 (必填)
  • 邮箱 (必填)
  • 网址