一次生产告警的完整排查记录。起因只是一条内容含糊的「mysql 备份失败」告警,最终却挖出了数据库被内核反复杀死 6 次、监控零告警、以及长达 14 小时的「零备份」状态。
前置说明:数据脱敏与时间约定
本文所有可识别信息均已脱敏,仅保留无标识性的技术细节。
脱敏策略
| 类别 | 处理方式 |
|---|---|
| 日期 | 一律用 t 日 表示(相对时间轴) |
| 时刻 | 一律用相对时间表示(t+0、t+36s、t+8h) |
| 星期 | 保留(对分析必要),但去掉具体日期 |
| ip / 主机名 / 域名 | 替换为示例值 / 占位符 |
| 数据库账号、库名、表名 | 替换为占位符 |
| 产品版本号 | 泛化为大版本(8.0.x) |
| lsn、表空间 id、进程 pid | 用占位符替代 |
| 容量、磁盘大小、数据量 | 取约数 |
| 内存数值与配置参数值 | 原样保留(技术核心,且无标识性) |
时间约定
t 日= 故障发生当天(某个周五)t+0= 备份任务启动时刻- 该主机上的时钟不稳定(见 §3.1 与 §12.7),因此本文一律使用相对时间轴,不引用绝对时刻
一、告警
企业微信告警群里收到这样一条消息:
【报警中】服务器 <db-host> ==================== 告警规则:mysql全库备份 告警级别:warning 主机名称:<db-host> 告警详情:mysql备份失败 告警状态:firing 触发时间:t 日(定时检查时刻) 发送时间:t 日(同上)
典型的「一句话告警」——只有结论,没有原因。
大多数人看到这种告警的第一反应是:登服务器,看看备份脚本是不是报错了、磁盘是不是满了、备份目录权限对不对。
这次的经验是:这个反应方向,从一开始就错了。
二、第一轮:先别急着登服务器
2.1 先分清这是「原因性告警」还是「结果性告警」
告警触发时刻是一个精确到秒的整点,这是重要线索。先去看监控规则本身,发现计划任务里有两类任务:
# 备份任务:每周固定一天,凌晨执行一次 <备份调度> /path/to/mysql_backup.sh # 检查任务:同一天,上午和下午各检查一次 <检查调度> /path/to/mysql_backup_monitor.sh
故障当天正好是执行备份的那个周五。
结论:备份任务在凌晨执行,这条告警只是「约 8 小时后的一次事后检查」。
告警时间 = 检查时间,而不是故障时间。 这一条认知直接决定接下来该查哪段日志。
2.2 判断影响面
只有这一台机器告警,同批次其他实例正常。
结论:大概率是单机局部问题,不需要在集群范围排查。
2.3 第一轮系统体检(全部只读)
# 基础环境 date; hostname; uptime; free -m # 磁盘与 inode(最高频元凶) df -ht df -i # mysql 是否健在 systemctl status mysqld --no-pager ps -ef | grep -ei "mysqld|mysqldump|xtrabackup" | grep -v grep ss -lntp | grep 3306 # oom 迹象 dmesg -t | grep -i -e "oom|killed process" | tail -10 # 计划任务与脚本定位 crontab -l grep -ril -e "mysqldump|xtrabackup" /etc/cron* /root /opt /scripts 2>/dev/null
2.4 第一轮就出现了反常信号
load average: 7.5, 7.4, 7.2
total used free shared buff/cache available
mem: 7980 7320 133 15 526 385
swap: 2047 660 1387| 指标 | 数值 | 判断 |
|---|---|---|
| 物理内存 | 7980 mb(约 8 gb) | — |
| 可用内存 | 385 mb | 🔴 危险 |
| swap 已用 | 660 mb | 🟠 |
| 连续运行时长 | 约 8 个月未重启 | — |
| 磁盘 | / 使用 23%、数据盘 32%、inode 1% | ✅ 排除磁盘因素 |
磁盘完全健康,但内存只剩 385 mb。 问题方向立刻转向内存。
三、关键转折:告警时间 ≠ 故障时间
3.1 一个差点被忽略的坑:dmesg -t时间不可信
查 oom 记录时发现一件事:同一个事件,三个来源给出了两个时间。
| 来源 | 显示时间 |
|---|---|
dmesg -t | 时刻 a |
/var/log/messages | 时刻 b |
systemctl status(journal) | 时刻 b + 2 秒 |
判定方法:比对两处日志的 mem-info 明细。
| 来源 | 显示时间 | active_anon | inactive_anon | slab_reclaimable | free |
|---|---|---|---|---|---|
dmesg -t | 时刻 a | 1584788 | 312434 | 16644 | 25697 |
/var/log/messages | 时刻 b | 1584788 | 312434 | 16644 | 25697 |
数字完全一致 → 这是同一个事件,只是时间戳不同。
最终以 /var/log/messages 和 journal 为准,理由有三:
- 两者互相印证,都指向时刻 b
- 时刻 b 正好是备份任务启动后的 36 秒
- mysqld 新进程的启动时间正是同一个整点
dmesg -t 为什么不准?
dmesg -t 的时间 = 内核记录的启动时刻(btime)+ 开机以来的单调时间。如果系统时钟在启动之后被 ntp 校正过,btime 不会同步更新,于是所有 dmesg -t 的时间都会整体偏移。
这台机器上偏移了约 29 分钟,而且这个偏移在更早的一次 oom 上同样存在,偏移量恒定。
经验:在时钟不稳定的机器上,涉及时间取证的场景一律以
journalctl//var/log/messages为准,不要用dmesg -t。
3.2 修正后的时间线
t+0s 备份脚本启动 t+0s ★ 脚本第一件事:删除上一周的备份目录 t+16s 清理完成 t+18s xtrabackup 启动 t+20s executing lock instance for backup ... t+20s → t+34s 14 秒空档(初始化本地 innodb、创建 logfile) t+36s ★ mysqld 被内核 oom killer 杀死 t+38s xtrabackup 报错:104 / 2013 连接中断 t+38s 备份脚本判定失败 t+8h 监控脚本检查发现失败,推送告警
备份任务不是故障原因,它是「正好撞上故障」的那个动作。
四、证据链:mysqld 被 oom killer 杀死
4.1 内核留下的原始证据
内核 oom 现场会打印所有进程的内存快照,其中 mysqld 那一行:
[ <pid> ] <uid> <pid> total_vm rss nr_ptes swapents oom_score_adj name
[ <pid> ] <uid> <pid> <...> 1832259 5008 416460 0 mysqld
↑rss(页) ↑swapents(页)
| 指标 | 页数 | 换算 |
|---|---|---|
| rss(驻留物理内存) | 1,832,259 | 6.99 gb |
| swapents(已换出到 swap) | 416,460 | 1.59 gb |
| 合计真实内存需求 | — | 8.58 gb |
| 物理内存总量 | 2,097,016 | 7.98 gb |
mysqld 想要 8.58 gb,机器只有 7.98 gb。
同时:
free swap = 0kb ← 2 gb swap 一个字节都不剩 inactive_anon:312434 ← 1.19 gb 想换出去但没地方放
swap 满 → 内核无法回收匿名页 → 只能启动 oom killer。
4.2 一个容易算错的账:rss ≠ 真实内存需求
排查内存问题时,ps 看到的 rss 只是物理内存部分,被换出到 swap 的部分不在里面。
真实内存需求 = rss + vmswap
# 正确的取值方法 pid=$(cat /path/to/mysql.pid) grep -e "vmrss|vmswap" /proc/$pid/status
本次:
- oom 时:
6.99 gb + 1.59 gb = 8.58 gb - 排查时:
6.72 gb + 0.29 gb = 7.01 gb
只看 rss 会低估 20% 以上的实际需求。
4.3 顺带发现:这台机器长期在疯狂换页
swap cache stats: add ~1.6e8, delete ~1.6e8
1.6 亿页 × 4 kb ≈ 600+ gb 累计换页量,开机约 8 个月 → 平均每天换页 2 gb 以上。
这不是偶发峰值,而是长期状态。
五、更严重的发现:数据库已经被打挂 6 次
排查过程中翻历史日志,看到了这样一串记录——在过去约三周内,mysqld 被内核杀死过 6 次。
5.1 逐条核对时段
| # | 时段 | 星期 | 是否备份时段 |
|---|---|---|---|
| 1 | 凌晨 | 周五 | ✅ 备份启动后约 50 秒 |
| 2 | 上午 | 周三 | ❌ |
| 3 | 凌晨 | 周一 | ❌ |
| 4 | 夜间 | 周三 | ❌ |
| 5 | 上午 | 周一 | ❌ |
| 6 | 凌晨 | 周五 | ✅ 备份启动后 36 秒 |
5.2 一个必须诚实修正的判断
排查早期,看到「有几次 oom 都落在凌晨同一时刻」,很容易得出**「是备份把数据库打挂的」**这个结论。
但逐条核对星期后发现:6 次里只有 2 次发生在备份时段,另外 4 次(周一、周三、白天、夜间)与备份毫无关系。
另外,oom 现场进程表里 xtrabackup 自身的 rss 只有 约 120 mb——xtrabackup 是文件级复制,不经过 buffer pool,它自己不占内存。
修正后的准确表述:
mysqld 长期处于内存临界状态,任意一个额外动作都可能把它推过阈值。每周备份是其中一类触发因素,而不是唯一原因。
这个修正很重要——它决定了后续的投入方向:要解决的是「内存不够」,而不是「备份脚本有 bug」。
5.3 最严重的监控盲区
数据库被内核杀死 6 次,监控系统一条告警都没有。
唯一的间接信号是「备份失败」——而且延迟约 8 小时。如果这 6 次里有任何一次发生在白天业务高峰,影响面会完全不同。
六、处置一:给数据库加 oom 护栏
6.1 原理
linux oom killer 选择受害者时,会给每个进程算一个 badness 分数:
分数 ≈ 该进程占用内存的比例 × 1000 + oom_score_adj
分数最高者被杀。mysqld 独占整机约 90% 内存,天然最高——内核日志里它的分数是 877,全场第一。
6.2 操作
# 保护当前 mysqld 进程 pid=$(cat /path/to/mysql.pid) echo -500 > /proc/$pid/oom_score_adj # 保护 mysqld_safe(守护壳),让未来自动重启的 mysqld 继承 echo -500 > /proc/<mysqld_safe_pid>/oom_score_adj
为什么要设 mysqld_safe?
oom_score_adj 是进程属性,fork 出的子进程会继承父进程的值:
mysqld_safe (设为 -500)
└── mysqld 崩溃 → mysqld_safe 自动重新拉起新的 mysqld
└── 新 mysqld 自动继承 -500 ✅
6.3 为什么是-500而不是-1000
-1000 表示「内核绝对不许杀它」。听起来更安全,但在这台机器上反而危险:
mysqld 约 7 gb ← 唯一的"大块头" 其余所有进程 约 0.2 gb ← 全是几十 mb 的小角色
如果 mysqld 变成「杀不得」,内核会发现杀了别人也救不回内存,可能引发连锁杀进程,甚至杀掉 sshd 让人失去登录能力。
-500 留了余地:既让 mysqld 排到后面,又不至于让内核「无路可走」。
6.4 更完整的方案:替罪羊机制
护栏的价值在于改变最坏结果的形态:
| 没有护栏 | 有护栏 | |
|---|---|---|
| 内存爆掉时 | mysqld 被杀 → 数据库宕机、业务中断、备份失败得不明不白 | 备份进程被杀 → 备份失败告警,数据库活着 |
配合备份脚本里的这一行(子进程继承):
echo 500 > /proc/$$/oom_score_adj # 备份进程主动当替罪羊
完整分工:
mysqld : -500 → 尽量别杀我 备份进程 : +500 → 我是可以牺牲的
本次事故恰好是反过来的:数据库被杀,备份反而「失败得不明不白」。
6.5 一个必须知道的限制
/proc/<pid>/oom_score_adj 只存在于内核内存里,不落盘。
| 情况 | 是否失效 |
|---|---|
| mysqld 被 oom 杀掉后自动重启 | ❌(除非父进程 mysqld_safe 也设了,可继承) |
执行 service mysql restart | ❌ 失效 |
| 机器重启 | ❌ 失效 |
要持久化,需要靠:systemd drop-in(oomscoreadjust)、patch init.d 脚本、或者每分钟 cron 自愈脚本兜底。
⚠️ 如果 crontab 是配置管理工具(ansible 等)下发的,手工 crontab -e 加的条目会被下次同步覆盖——要走配置管理流程,或写到独立的 /etc/cron.d/ 文件里。
七、处置二:buffer pool 4g → 3g
7.1 先算清楚 buffer pool 到底占了多少
select @@innodb_buffer_pool_size/1024/1024 as bufpool_mb;
show global status where variable_name in
('innodb_buffer_pool_pages_data','innodb_buffer_pool_pages_free','innodb_buffer_pool_pages_total');
bufpool_mb = 4096 pages_total = 262144 × 16 kb = 4096 mb pages_data = 261744 × 16 kb = 4090 mb pages_free = 175 × 16 kb = 2.7 mb
占用率 = 261744 ÷ 262144 = 99.93%
三个结论:
| # | 含义 |
|---|---|
| ✅ | 池子已被彻底填满 → 调小它一定能把内存还给系统(不会出现「池子本来没填满、调了也省不出」的情况) |
| ⚠️ | 工作集已超过 4 gb(池子 100% 占用仍有持续物理读)→ 调小后物理读会增加,性能会降 |
| 🔴 | 反向印证异常:池子只要 4 gb,mysqld 却占了 6.7 gb |
7.2 执行在线调整
set global innodb_buffer_pool_size = 3221225472; -- 3 gb
参数说明:
3221225472 = 3 × 1024³,即 3 gb- 调整粒度 =
innodb_buffer_pool_chunk_size×innodb_buffer_pool_instances=128m × 8= 1 gb,所以必须是整数 gb - 从 mysql 5.7.5 起支持在线伸缩,不需要重启、不中断业务
验证:
select @@innodb_buffer_pool_size/1024/1024 as bufpool_mb; show status like 'innodb_buffer_pool_resize_status';
缩容过程中状态会显示进度:
buffer pool 7 : withdrawing blocks. (8177/8192)
这句的含义:8 个 buffer pool instance 逐个回收,7 是最后一个(编号 0~7),8177/8192 是完成度——看到这个说明已经跑到 99.8% 了。
8192 页 × 16 kb = 128 mb,正是待回收的 1024 mb chunk 分摊到单个 instance 的分量。
等它变成 completed resizing buffer pool at ... 才算完。
7.3 实测效果
| 指标 | 改前 | 改后 | 变化 |
|---|---|---|---|
memavailable | 304 mb | 1353 mb | +1049 mb ✅ |
used | 7406 mb | 6357 mb | −1049 mb |
mysqld vmrss | 6.72 gb | 5.72 gb | −1.00 gb ✅ |
swap used | 745 mb | 745 mb | 无变化(没产生新交换) |
预测 vs 实际:
预测归还:65,136 页 × 16 kb = 1,017 mb 实际归还:1,053,856 kb = 1,029 mb
误差 12 mb。 说明「buffer pool 100% 占用」这个判断是准确的。
7.4 持久化(千万别漏)
cp -a /etc/my.cnf /etc/my.cnf.bak.$(date +%y%m%d_%h%m%s) sed -i 's/^innodb-buffer-pool-size[[:space:]]*=.*/innodb-buffer-pool-size = 3g/' /etc/my.cnf # 确认只改了一行 diff $(ls -t /etc/my.cnf.bak.* | head -1) /etc/my.cnf # ★ 确认 mysql 能正确解析(防止文件写坏导致下次起不来) /usr/local/mysql/bin/my_print_defaults mysqld | grep -i "buffer-pool-size"
最后一条必须输出 --innodb-buffer-pool-size=3g。
set global只改运行时,不持久化。 不写 my.cnf,下次重启就全回退了。
7.5 代价:性能确实会降
对比调整前后的 vmstat:
| 指标 | 4g 池 | 3g 池 | 变化 |
|---|---|---|---|
磁盘读 bi | 1.6~2.5 mb/s | 11~14 mb/s | ↑ 约 6 倍 |
cpu 空闲 id | 45%~72% | 10%~26% | ↓ 大幅下降 |
i/o 等待 wa | 0%~6% | 8%~17% | ↑ |
原因:工作集超过 4 gb,池子只剩 3 gb → 缓存命中率下降 → 反复读磁盘。
这是「用性能换安全」。 但它同时说明:真正的解是扩内存,而不是把池子调回 4g(调回去就又回到 oom 边缘)。
八、处置三:发现「零备份」状态
8.1 一个反直觉的发现
准备重跑备份前,先看了一眼备份产物目录:
/data/backup/data/<当天日期>/ ├── my.cnf 14,298 b ← 是脚本拷过来的配置文件 └── xtrabackup_logfile 12.7 mb ← 只有日志文件
没有 .ibd、没有 ibdata1、没有 xtrabackup_checkpoints。这是一份完全不可用的残骸。
翻备份脚本的日志,第一行就写明了原因:
[<时间>] removing expired backup data: /data/backup/data/<上周日期>
8.2 问题出在清理策略
备份脚本的清理逻辑:
for target in $(find "${base_path}/data" -maxdepth 1 -mindepth 1 -type d -mtime +5); do
rsync -a --delete "$empty_dir/" "$target/"
rmdir "$target"
done- 备份周期:每周一次
- 清理阈值:
-mtime +5(6 天以上)
上周的备份此时已经 7 天 → 每次运行都会先把上一份删掉,再建新的。
🔴 结论:只要本次备份失败,就一份备份都不剩。
本次故障中,脚本启动第一件事就删掉了上一周的备份,然后自己失败了 → 该实例在约 14 小时内处于「零备份」状态。
8.3 这个发现的性质变了
❌ 不是「备份失败」级别的问题 ✅ 是「数据保护空窗」级别的问题
「先删后建」是备份策略里的经典反模式。 正确做法:
- 先建新备份
- 本次备份成功并校验通过后,再清理过期备份
- 至少保留 2 份
九、备份脚本的问题清单
完整读了一遍备份脚本后,整理出 8 个问题:
| # | 缺陷 | 影响 | 严重度 |
|---|---|---|---|
| 1 | 清理策略「先删后建」,阈值比备份周期还短,实际只保留 1 份 | 备份失败 = 零备份 | 🔴 |
| 2 | 无内存闸门 | 内存不足时硬跑,可能打挂数据库 | 🔴 |
| 3 | 无完整性校验(只看退出码) | 坏备份被判定为成功 | 🟠 |
| 4 | 失败无即时告警 | 最长 8 小时后才由检查脚本发现 | 🟠 |
| 5 | 使用裸 mysql 命令,cron 的 path 下找不到 | 超时延长逻辑从未生效 | 🟡 |
| 6 | cp my.cnf $backup_dir 无条件执行 | 失败目录里也有文件,易被误判为「有内容」 | 🟡 |
| 7 | 备份与数据库同盘 | 该盘故障则库与备份同时丢失 | 🟠 |
| 8 | --safe-slave-backup 是空操作 | 实例并非从库,属历史遗留配置 | 🟡 |
9.1 关于第 5 条的细节
脚本里有一段「临时延长网络超时」的逻辑,日志显示:
extended timeouts to 3600s. original read: unknown, write: unknown
unknown 说明取原值的命令执行失败了——脚本用的是裸 mysql 命令,而 cron 的 path 只有 /usr/bin:/bin,找不到装在自定义目录下的客户端。于是:
- 原值为空 →
set global没执行 - 回滚步骤也因为值为空被跳过
修复:脚本里所有 mysql 改成绝对路径。
顺带一提:脚本的失败信息里写着类似 check pt-kill whitelist if 104/2013 error persists 的提示——说明作者之前也遇到过 104/2013 连接中断,并且一直在往「连接被掐断」的方向排查(怀疑 pt-kill、网络超时)。而这次终于拿到了答案:是内核把数据库杀掉了,跟 pt-kill 完全无关。
9.2 一个安全提醒
不要用 bash -x 调试这个脚本。
脚本会 source 一个存放凭据的 .env 文件,bash -x 会把 db_user=xxx / db_pass=yyy 明文打进日志。
调试应该用「外层包装脚本 + 脚本自身的日志文件」,而不是 -x。
十、监控脚本的 fail-open 问题
读监控脚本时发现一个更隐蔽的缺陷:
last_line=$(tail -n 1 "$log_file" 2>/dev/null) case "$last_line" in *"mysql full_backup failed"*) cur_status="failed" ;; *"mysql full_backup succeed"*) cur_status="success" ;; *) cur_status="success" ;; # ← 危险 esac
默认分支是 success(fail-open)。 只要最后一行既不匹配 failed 也不匹配 succeed,它就当成功处理。
什么情况下会这样?
| 场景 | 最后一行 | 监控判定 |
|---|---|---|
🔴 备份进程被 pkill 掐断 | xtrabackup 的某条 note | success(误报) |
🔴 脚本在凭据检查处 exit 1 | error: env file not found! | success(误报) |
| 🔴 脚本启动后立刻被杀 | workflow started... | success(误报) |
「误报成功」比「漏报」更危险——它会让人以为问题解决了。
另一个盲区:
[ -f "$log_file" ] || exit 0 # 日志不存在就静默退出
备份压根没跑(日志文件不存在)时,不告警。
修复建议
- 默认分支改成
failed(fail-closed),或者更严格:只认显式的succeed标记 - 日志文件不存在时应该告警,而不是静默退出
- 验收不能只看监控推送的「已恢复」消息——必须人工核对
xtrabackup_checkpoints
十一、补跑备份成功
11.1 前置动作
xtrabackup 拒绝写入非空的 --target-dir,而备份脚本的目标目录是当天日期,重跑会撞上凌晨留下的残骸目录。
mv /data/backup/data/<当天日期> /data/backup/data/<当天日期>.failed
用 mv 而不是 rm,保留现场。
顺带确认:新名字的 mtime 是当天,不会被 -mtime +5 的清理逻辑误删。
11.2 要不要先重启?
调参后可用内存约 1.3 gb。评估:
备份增量 ≈ 1.8 gb(按上次 oom 的差额估算) 当前余量 = available 1.3 gb + swap 空闲 1.3 gb ≈ 2.6 gb
够,但只有 40% 余量,所以决定:加护栏直接跑,而不是先重启(重启要等窗口,且护栏已经把最坏结果兜住了)。
后来实测证明这个估算偏保守——xtrabackup 自身 rss 只有约 120 mb,那 1.8 gb 的差额更可能是 mysqld 自身长期累积的结果,而不是备份造成的。
11.3 包装脚本(不改原脚本)
cat > /tmp/run_backup_safe.sh <<'eof'
#!/bin/bash
# 1) 内存爆时优先杀我(子进程继承),保 mysqld
echo 500 > /proc/$$/oom_score_adj
# 2) 内存闸门
avail=$(awk '/memavailable/{print int($2/1024)}' /proc/meminfo)
echo "[$(date '+%f %t')] 启动前 memavailable = ${avail} mb"
if [ "$avail" -lt 1000 ]; then
echo "[$(date '+%f %t')] 【中止】可用内存仅 ${avail}mb(阈值 1000mb),放弃备份以免打挂数据库"
exit 1
fi
free -m
echo "[$(date '+%f %t')] ===== 备份开始 ====="
nice -n 19 ionice -c2 -n7 /bin/bash /data/backup/mysql_backup.sh
rc=$?
echo "[$(date '+%f %t')] ===== 备份结束,退出码 = $rc ====="
free -m
exit $rc
eof
chmod +x /tmp/run_backup_safe.sh
nohup /tmp/run_backup_safe.sh > /tmp/backup_run_$(date +%m%d_%h%m).log 2>&1 &这层包装做了四件事:
oom_score_adj = 500→ 内存爆时死的是备份,不是数据库- 内存闸门 → 不足 1 gb 直接放弃,不硬跑
nice -n 19 ionice -c2 -n7→ 最低 cpu/io 优先级,尽量不干扰业务- 日志落盘 → 断线也能查
用原脚本而不是手工跑 xtrabackup,这样日志里会正常写下
mysql full_backup succeed,监控脚本才认。
11.4 护栏分工验证(关键)
mysqld oom_score_adj = -500 ← 数据库被保护 mysqld_safe oom_score_adj = -500 ← 自动重启也继承保护 备份脚本(bash) oom_score_adj = 500 ← 备份主动当替罪羊 xtrabackup oom_score_adj = 500 ← 子进程继承
11.5 结果
| 项目 | 结果 |
|---|---|
| 耗时 | 约 31 分钟 |
| 退出码 | 0 |
| xtrabackup | completed ok! |
| 脚本日志末行 | mysql full_backup succeed |
| 备份产物 | 约 160 gb(与数据目录体积吻合) |
| 运行期 mysqld rss | 5.76 gb → 5.77 gb(几乎不动) |
全程无 oom,护栏没有被用上。
完整性校验(xtrabackup_checkpoints):
backup_type = full-backuped ← 全量,非增量 from_lsn = 0 ← 从 lsn 0 开始 = 完整全量 to_lsn = <有具体数值> ← 备份一致性点 last_lsn = <大于 to_lsn,正常> ← redo 复制到的位置 flushed_lsn = <有具体数值> redo_memory = 0 redo_frames = 0
redo 日志复制范围连续无断档——这是备份能恢复的前提。
11.6 别急着--prepare
xtrabackup 的备份是未 prepare 状态,恢复前必须执行:
xtrabackup --prepare --use-memory=256m --target-dir=/data/backup/data/<当天日期>
--prepare 会按 my.cnf 里的 innodb_buffer_pool_size 分配内存(此时是 3g),在内存紧张的机器上必须加 --use-memory 限制。
关键认知:备份存在 ≠ 备份可恢复。
而且——过去每周的备份都在下一周被自动删掉了,从来没有任何一份备份被验证过能不能恢复。
十二、继续深挖:那 3 gb 内存去哪儿了
12.1 做减法
mysqld 实际内存 6.13 gb (rss 5.85 + swap 0.28) ├─ innodb_buffer_pool 2.99 gb (195,781 页 × 16kb) └─ buffer pool 之外 3.14 gb ← 问题所在
一个 3 gb buffer pool 的实例,正常总共应该占 4~4.5 gb,现在占了 6.13 gb。
12.2 用 performance_schema 找归属
select event_name, current_alloc from sys.memory_global_by_current_bytes order by current_alloc desc limit 20;
(注意:sys 视图的列名在不同版本间有差异,遇到 unknown column 时改用底层表performance_schema.memory_summary_global_by_event_name 更稳,或直接 select *。)
结果:
memory/innodb/buf_buf_pool 3.07 gib ← buffer pool(正常) memory/mysys/io_cache 1.09 gib ← 🔴 头号异常 memory/performance_schema/table_handles 72.50 mib memory/sql/table 70.16 mib memory/temptable/physical_ram 61.00 mib memory/performance_schema/* (其余 8 项) ~233 mib memory/innodb/* (log_buffer 等) ~128 mib memory/sql/dd::* / table_share ~48 mib
账对上了:3.07 + 1.09 + 0.30 + 0.30 + 0.13 + 约 1.4(pfs 未覆盖部分)≈ 6.13 gib。
12.3 头号异常:memory/mysys/io_cache≈ 1.1 gib
io_cache 是什么:mysql 内部的文件顺序读写缓存结构,主要出现在:
filesort排序落盘、大查询排序load data infile/select ... into outfilealter table拷贝表binlog dump线程(每个连上来的从库各分配一个)- 复制 sql/io 线程读 relay log
量化它:
select event_name,
current_count_used as 块数,
round(current_number_of_bytes_used/1048576,1) as 总计mb,
round(current_number_of_bytes_used/current_count_used/1024,1) as 平均kb,
round(high_number_of_bytes_used/1048576,1) as 历史峰值mb
from performance_schema.memory_summary_global_by_event_name
where event_name like '%io_cache%';
memory/mysys/io_cache | 约 1600 块 | ~1.1 gb | 平均约 690 kb | 历史峰值 ~1.5 gb
形态:不是「一个超大块」,而是「大量中等大小的块」——说明来自大量重复的、规模相近的操作。
周转量:
累计分配 约 68 万块 / 约 35 gb 累计释放 约 67.7 万块 / 约 34 gb 当前持有 约 1600 块 / ~1.1 gb
15 小时里分配了约 68 万次(约 12.6 次/秒)。
12.4 一个未解的矛盾
按线程统计:
select round(sum(current_number_of_bytes_used)/1048576,1) from performance_schema.memory_summary_by_thread_by_event_name where event_name='memory/mysys/io_cache';
全局mb = 约 1160 线程合计mb = null ← null = 零行!
sum() 在零行上返回 null。也就是说:全局计数器说有约 1.1 gb,但没有任何存活线程持有它。
全局 io_cache ~1.1 gb
所有线程内存合计(全部类型) ~170 mb
─────────
约 900 mb 无归属
这块内存无法通过「kill 连接」释放——因为它不属于任何线程。
12.5 关于「是不是内存泄漏」,必须诚实
观测到的数据:
| 采样点 | io_cache | 块数 |
|---|---|---|
| 采样 1 | ~1.10 gb | 1640 |
| 采样 2 | ~1.16 gb | 1724 |
| 采样 3 | ~1.09 gb | 1628 |
| 采样 4 | ~1.09 gb | 1628 |
数值会回落(1724 → 1628),且在 5 分钟观测窗口内完全不变。
所以这不是「只增不减」的硬性内存泄漏。 早期一度得出「确认泄漏」的结论,被这组数据推翻了。
准确表述:mysql 里长期驻留约 1.1 gb 的 io_cache(波动 1.1~1.5 gb),且没有任何线程对它负责。
12.6 真正要命的发现:增长不在 io_cache
| 采样点 | mysqld 总内存 | buffer pool | buffer pool 之外 |
|---|---|---|---|
| 调参前 | 7.01 gb | 4.09 gb | 2.92 gb |
| 调参后约 1 小时 | 6.13 gb | 2.99 gb | 3.14 gb |
约 2 小时内「buffer pool 之外」涨了约 220 mb(约 110 mb/小时),而 io_cache 在这期间基本持平。
io_cache 是一块「大但稳定」的常驻开销,不是增长源。真正在涨的东西,当时还没有找到。
这一步的诚实结论比强行给一个答案更重要。
12.7 顺带发现的两个问题
① 负载异常:一条 select 在 15 小时内执行了约 154 万次
select left(digest_text,60) as 语句, count_star as 执行次数,
sum_sort_merge_passes as 归并排序次数,
sum_created_tmp_disk_tables as 磁盘临时表次数,
sum_sort_rows as 排序行数
from performance_schema.events_statements_summary_by_digest
order by sum_sort_merge_passes desc limit 10;
select `id`,`account_id`,`account_name`,`city_id`... | 约 154 万次
约 28.6 次/秒,持续不断。 这是应用里的轮询循环在打数据库,值得让开发排查。
② 这台机器的时钟不稳定
测试时钟稳定性时发现:
某时刻 → [select sleep(300)] → now() 只前进了 60 秒
select sleep(300) 正常返回(说明确实睡了 300 秒),但前后 now() 只差 60 秒 → 系统时钟在这期间被往回拨了约 4 分钟。
这和最初发现的「dmesg -t 比 rsyslog 慢 29 分钟」是同一类现象。
这台机器的时钟稳定性有问题,会影响所有日志时间取证的可靠性,建议单独排查(ntp 配置、虚拟化时钟源)。
十三、结论与遗留问题
13.1 已经确定的
| 结论 | 依据 |
|---|---|
| 故障根因是内核 oom killer 杀死 mysqld,备份只是触发器之一 | oom 现场内存数据、日志时间线 |
| 数据库历史上已被杀死 6 次,其中 4 次与备份无关 | journal 记录逐条核对时段 |
| 数据库被杀死 6 次,监控零告警 | 只有「备份失败」这一个间接信号 |
| 备份脚本「先删后建」导致故障期间零备份约 14 小时 | 脚本日志第 2 行 |
| buffer pool 4g → 3g 回收约 1.0 gb,预测误差 12 mb | 调整前后实测 |
备份已补跑成功(completed ok,退出码 0) | checkpoints + 日志 |
| io_cache 长期占用约 1.1 gb,峰值约 1.5 gb | pfs 全局计数器 |
| 应用侧有一条 select 在 15 小时内执行了约 154 万次 | digest 统计 |
13.2 还没确定的
| 待查项 | 说明 |
|---|---|
| ❓ 「buffer pool 之外」那约 110 mb/小时 的增长是什么 | 已排除 io_cache、磁盘、连接数 |
| ❓ io_cache 的约 1.1 gb 为什么没有线程归属 | pfs 记账局限?还是无主内存? |
| ❓ 约 700 个连接(全部来自同一台应用服务器)是否合理 | 需要应用侧确认连接池配置 |
| ❓ 时钟不稳会不会影响后续所有日志取证 | 建议单独排查 ntp / 虚拟化时钟 |
| ❓ 该 mysql 小版本是否存在 io_cache 相关的已知问题 | 需查官方 bug 库与 release notes |
不建议现在就下「根因已完全找到」的结论。
13.3 已识别但尚未执行的行动项
| 优先级 | 事项 |
|---|---|
| 🔴 高 | 查清「buffer pool 之外」内存的增长源 |
| 🔴 高 | 补齐告警:mysqld 进程存活、内存水位、swap 使用率、oom 事件、io_cache 水位 |
| 🟠 中 | 修复备份脚本 8 项缺陷(先删后建 / 内存闸门 / 完整性校验 / 即时告警 / 路径 / 异盘) |
| 🟠 中 | 修复监控脚本 fail-open 缺陷 |
| 🟠 中 | 安排一次恢复演练(--prepare + 恢复到测试实例) |
| 🟠 中 | 备份产物迁至异盘/异地 |
| 🟡 低 | 排期内存扩容至 16 gb |
| 🟡 低 | 延长系统日志保留周期(当时只剩 2 条 oom 记录) |
| 🟡 低 | 排查系统时钟不稳 |
十四、经验总结
14.1 告警处理
1. 先分清「原因性告警」和「结果性告警」
本次告警在上午发出,真实故障在凌晨发生,相隔约 8 小时。先看监控规则的判定逻辑和触发时刻,再决定查哪段日志。
2. 别被「告警标题」带走方向
标题是「mysql 备份失败」,实际故障是「数据库被内核杀死」。
告警标题描述的是「被发现的症状」,不是「故障本身」。
3. 只有一台机器告警 → 先按单机问题排查
影响面能大幅缩小排查范围。
14.2 内存问题排查
4. rss 不是真实内存需求,rss + vmswap 才是
本次 oom 时 mysqld 的 rss 是 6.99 gb,但加上 1.59 gb 的 swap,真实需求是 8.58 gb,而机器只有 7.98 gb。只看 rss 会严重低估。
5. 用「做减法」定位内存去向
mysqld 总内存 − buffer pool 真实占用 = 待解释的部分
再用 performance_schema 的 memory_global_by_current_bytes 把它拆开。
先用全局视图找大头,再用按线程视图找归属。
6. set global 一定要顺手持久化
在线调参只改运行时。不写配置文件,下次重启全回退。 写完后用 my_print_defaults 验证语法,避免配置文件写坏导致下次起不来。
7. 调小 buffer pool 是有性能代价的
本次调整后磁盘读涨了约 6 倍、cpu 空闲从 45%~72% 掉到 10%~26%。
这是「用性能换安全」,不是免费的。 同期就该把「扩内存」排上日程。
8. dmesg -t 在时钟不稳的机器上不可信
这类机器上做时间取证,一律以 journalctl / /var/log/messages 为准。
判定同一事件的方法:比对两处日志的细节数字(如 mem-info)是否完全一致。
14.3 变更操作
9. 先加护栏,再动手
在任何涉及内存/资源的变更之前,先花 30 秒加上 oom 护栏。
它不能阻止故障,但能改变故障的形态——把「数据库宕机」变成「备份失败」,这两件事的成本差一个量级。
10. 护栏要成对使用
被保护的(数据库) : oom_score_adj = -500 可牺牲的(备份进程): oom_score_adj = +500
只保护一方没有意义——如果整个系统只有一个大块头,内核无路可走时可能引发杀进程风暴。
11. 变更前先备份配置,变更后先验证语法
cp -a /etc/my.cnf /etc/my.cnf.bak.$(date +%y%m%d_%h%m%s) # ... 修改 ... /usr/local/mysql/bin/my_print_defaults mysqld | grep -i <改动的参数>
14.4 备份与监控
12. 「先删后建」是备份策略的经典反模式
清理动作必须放在本次备份成功并校验通过之后,且至少保留 2 份。
否则一次失败就等于把仅有的保护也一起弄没了。
13. 「任务返回 0」不等于「备份可用」
必须校验:
- mysqldump:结尾有
dump completed on ...+gzip -t通过 - xtrabackup:
xtrabackup_checkpoints的backup_type/from_lsn/to_lsn完整 + 日志有completed ok! - 最终标准:做过一次恢复演练
14. 监控脚本要 fail-closed,不要 fail-open
本次监控脚本的 case 默认分支是 success——备份进程被掐断、脚本早期退出,都会被判定为「备份已恢复」,推送一条假的好消息。
「误报成功」比「漏报」更危险。
15. 补告警时优先补「过程指标」而不是「结果指标」
本次的最大盲区是:数据库被内核杀死 6 次,没有任何独立告警,只靠「备份失败」这个 8 小时后才发出的结果指标间接暴露。
应该直接监控:进程存活、内存水位、swap 使用率、oom 事件。
14.5 沟通与记录
16. 及时修正自己的判断
本次排查中,有两个判断被后续数据推翻:
- 「有 3 次 oom 落在备份时段」→ 逐条核对后是 2 次
- 「确认是内存泄漏」→ 数据表明数值会回落,不是单调泄漏
发现说重了就说重了。 一个被修正过的准确结论,比一个听起来很确定的错误结论有价值得多。
17. 保留证据
- 变更前后的对照数据(本次的
available304 mb → 1353 mb 就是最有力的证明) - 日志原文(尤其是失败时刻的原始报错)
- 时间线(用「谁在什么时候做了什么」的格式)
本次排查过程中,有一条被忽略很久的线索:登录时反复出现的「有新邮件」提示。翻到最后一封是 ntp 的定时任务邮件,没有备份失败邮件——这个「没有」本身也是信息:说明备份脚本失败时不发通知,完全依赖 8 小时后的检查脚本。
附录 a:命令速查
a.1 内存体检
{
echo "================ 内存体检 $(date '+%f %t') ================"
echo; echo "【1】整机内存"; free -m
echo; echo "【2】mysqld 实际内存"
pid=$(cat /path/to/mysql.pid)
grep -e "vmrss|vmswap|vmsize" /proc/$pid/status
rss=$(grep vmrss /proc/$pid/status | awk '{print $2}')
swp=$(grep vmswap /proc/$pid/status | awk '{print $2}')
awk -v r=$rss -v s=$swp 'begin{printf ">>> 合计 %.2f gb\n", (r+s)/1048576}'
echo; echo "【3】swap 抖动"; vmstat 1 3
echo; echo "【4】oom 记录"; grep -h "killed process" /var/log/messages | tail -10
echo; echo "【5】内存 top10"; ps aux --sort=-rss | head -11
}
a.2 mysql 内存归属
-- 全局内存分布
select event_name, current_alloc
from sys.memory_global_by_current_bytes
order by current_alloc desc limit 20;
-- 底层表版本(避免 sys 视图列名差异)
select event_name,
round(current_number_of_bytes_used/1048576,1) as mb,
current_count_used as blocks
from performance_schema.memory_summary_global_by_event_name
where current_number_of_bytes_used > 0
order by current_number_of_bytes_used desc limit 20;
-- buffer pool 真实占用
select @@innodb_buffer_pool_size/1024/1024 as bufpool_mb;
show global status where variable_name in
('innodb_buffer_pool_pages_data','innodb_buffer_pool_pages_free','innodb_buffer_pool_pages_total');
-- 连接数与峰值
show global status where variable_name in
('threads_connected','threads_running','max_used_connections','uptime');
-- 连接来源分布
select user, host, count(*) as conns
from information_schema.processlist
group by user, host order by conns desc limit 20;
-- 排序/临时表大户
select left(digest_text,60) as stmt, count_star,
sum_sort_merge_passes, sum_created_tmp_disk_tables, sum_sort_rows
from performance_schema.events_statements_summary_by_digest
order by sum_sort_merge_passes desc limit 10;
a.3 oom 护栏
# 查看
for p in $(pgrep -f 'mysqld|mysqld_safe'); do
printf "%-15s pid=%-7s adj=%s\n" "$(cat /proc/$p/comm)" "$p" "$(cat /proc/$p/oom_score_adj)"
done
# 设置
pid=$(cat /path/to/mysql.pid)
echo -500 > /proc/$pid/oom_score_adj
# 每分钟自愈脚本(防重启失效)
cat > /usr/local/sbin/mysql_oom_guard.sh <<'eof'
#!/bin/bash
pidf=/path/to/mysql.pid
adj=-500
pid=$(cat "$pidf" 2>/dev/null)
[ -n "$pid" ] && [ -d "/proc/$pid" ] || exit 0
cur=$(cat "/proc/$pid/oom_score_adj" 2>/dev/null)
if [ "$cur" != "$adj" ]; then
echo "$adj" > "/proc/$pid/oom_score_adj" 2>/dev/null
logger -t mysql_oom_guard "mysqld($pid) oom_score_adj: ${cur:-na} -> $adj"
fi
eof
chmod +x /usr/local/sbin/mysql_oom_guard.sh
a.4 buffer pool 在线调整
-- 调整(注意必须是 chunk_size × instances 的整数倍,本例为 1 gb) set global innodb_buffer_pool_size = 3221225472; -- 3 gb -- 确认 select @@innodb_buffer_pool_size/1024/1024 as bufpool_mb; show status like 'innodb_buffer_pool_resize_status';
# 持久化 + 验证 cp -a /etc/my.cnf /etc/my.cnf.bak.$(date +%y%m%d_%h%m%s) sed -i 's/^innodb-buffer-pool-size[[:space:]]*=.*/innodb-buffer-pool-size = 3g/' /etc/my.cnf grep -n "innodb-buffer-pool-size" /etc/my.cnf /usr/local/mysql/bin/my_print_defaults mysqld | grep -i "buffer-pool-size"
a.5 备份验收
# 进程 pgrep -af 'xtrabackup|mysql_backup' || echo "已结束" # 任务退出码 tail -6 /tmp/backup_run_*.log # 脚本日志末行(必须是 succeed) tail -5 /data/backup/log/$(date +%y%m%d)/mysql_backup_3306.log # ★ 完整性校验 cat /data/backup/data/$(date +%y%m%d)/xtrabackup_checkpoints grep -i "completed ok" /data/backup/log/$(date +%y%m%d)/mysql_backup_3306.log ls /data/backup/data/$(date +%y%m%d)/ | wc -l du -sh /data/backup/data/$(date +%y%m%d)
附录 b:完整时间线
全部使用相对时间轴:
t+0= 备份任务启动时刻
b.1 故障发生(t 日凌晨)
| 相对时间 | 事件 |
|---|---|
| t+0s | 备份脚本启动,第一件事:删除上一周的备份 |
| t+16s | 清理完成;网络超时延长逻辑执行失败(original read: unknown) |
| t+18s | xtrabackup 启动,识别服务端参数 |
| t+20s | executing lock instance for backup ... |
| t+20s → t+34s | 14 秒空档(初始化本地 innodb、创建 logfile)——压力最高的窗口 |
| t+36s | 💀 mysqld 被内核 oom killer 杀死 |
| t+38s | xtrabackup 报 104 / 2013 连接中断 |
| t+38s | 脚本判定失败,写入 mysql full_backup failed |
| t+8h | 监控脚本检查发现失败,推送告警 |
b.2 应急处置(同日白天)
| 相对时间 | 动作 | 关键结果 |
|---|---|---|
| t+10.8h | 系统体检 | 磁盘正常;available 仅 385 mb |
| t+11h | 采集 mysql 参数 | buffer pool 4g、max_connections 10000、max_allowed_packet 1g |
| t+11.1h | 采集 oom 现场 | 发现 dmesg -t 与 rsyslog 时间不一致(约 29 分钟偏差) |
| t+13h | 复查内存 | available 降至 237 mb,问题在恶化 |
| t+13.9h | 加 oom 护栏 | mysqld / mysqld_safe 均设为 -500 |
| t+13.9h | buffer pool 4g → 3g | 回收 约 1.0 gb;available 304 → 1353 mb |
| t+14h | 持久化 my.cnf | diff 确认只改一行;my_print_defaults 验证通过 |
| t+14.1h | 读取备份脚本逻辑 | 发现清理策略为「先删后建」 |
| t+14.2h | 挪走凌晨的残骸目录 | xtrabackup 要求目标目录为空 |
| t+14.2h | 带护栏补跑备份 | 包装脚本:内存闸门 + oom 替罪羊 + 低优先级 |
| t+14.5h | 备份进行中 | mysqld rss 稳定在 5.77 gb,未上涨 |
| t+14.7h | 备份完成 | 约 160 gb,退出码 0,completed ok! |
| t+15h | 内存复查 | available 1185 mb;mysqld 6.13 gb |
| t+15.2h | 内存归属分析 | 锁定 io_cache ≈ 1.1 gib |
| t+15.3h | 泄漏量化 | 累计分配约 68 万次,当前持有约 1600 块 |
| t+15.4h | 泄漏速率观测 | 5 分钟内数值完全不变 → 推翻「单调泄漏」判断 |
b.3 内存账本对照
| 阶段 | available | mysqld 总内存 | buffer pool | buffer pool 之外 |
|---|---|---|---|---|
| 初始体检 | 385 mb | ~6.6 gb | 4.09 gb | — |
| 复查(最低点) | 237 mb | 7.01 gb | 4.09 gb | 2.92 gb |
| 调参后 | 1353 mb | 6.01 gb | 3.00 gb | 3.01 gb |
| 备份中 | 1142 mb | 6.06 gb | 2.99 gb | — |
| 备份结束 | 1259 mb | 6.06 gb | 2.99 gb | — |
| 调参后约 1 小时 | 1185 mb | 6.13 gb | 2.99 gb | 3.14 gb |
写在最后
这次事件的起点,是一条只有 6 个字有效信息的告警:
告警详情:mysql备份失败
如果当时按字面意思去查备份脚本、查磁盘、查权限,大概率会陷入「手动跑一遍备份成功了 → 告警消除 → 下周照旧」的循环。
真正让事情有进展的,是三个「不按直觉走」的动作:
- 问了一句「这个告警是什么时候、按什么规则发出来的」——发现它比故障晚了 8 小时
- 算了一笔账「rss + swap 到底是多少」——发现数据库的真实内存需求已经超过物理内存
- 在动手改参数之前,先花 30 秒加了护栏——保证了后续所有操作的最坏结果都是可控的
以及一条贯穿全程的原则:
数据推翻结论时,改结论,不要改数据。
本次排查中有两个判断被自己推翻——「有 3 次 oom 落在备份时段」和「确认是内存泄漏」。修正它们让结论变得更弱,但也变得更真。
一条准确的、承认边界的结论,比一条听起来很确定的错误结论有用得多。
以上就是mysql备份失败告警的排查与解决方法的详细内容,更多关于mysql备份失败告警的资料请关注代码网其它相关文章!
发表评论