某日凌晨收到db故障告警,上机器检查,mysql已经被myqld守护进程重新启动。检查/var/log/messages和最近的dmesg发现mysql进程是被oom干掉了。
信息大概摘录如下:
[13045702.638964] kthread invoked oom-killer: gfp_mask=0xd0,
order=1, oomkilladj=0
[13045702.638969]
[13045702.638969] Call Trace:
<ffffffff8014a331>{oom_kill_process+87}
[13045702.638977]
<ffffffff8014a722>{out_of_memory+271}
<ffffffff8013ce59>{autoremove_wake_function+0}
ERROR: Fatal error found, match ERROR-KEYWORD 'out_of_memory'
...
[13045702.716335] Out of Memory: Kill process 25795
(mysqld) score 1591671 and children.
ERROR: Fatal error found, match ERROR-KEYWORD 'Out of Memory'
[13045702.716359] Out of memory: Killed process 25795
(mysqld).
.....
[13045702.802080] Out of Memory: Kill process 1907 (mysqld)
score 955002 and children.
ERROR: Fatal error found, match ERROR-KEYWORD 'Out of Memory'
[13045702.802102] Out of memory: Killed process 1907
(mysqld).
....
[13045762.203463] Out of Memory: Kill process 24544 (mysqld)
score 341071 and children.
ERROR: Fatal error found, match ERROR-KEYWORD 'Out of Memory'
[13045762.203485] Out of memory: Killed process 24544 (mysqld).
[13045762.322333] sap1002 invoked oom-killer: gfp_mask=0x201d2,
order=0, oomkilladj=0
.....
[13045762.479886] Out of Memory: Kill process 19530
(mysqldump) score 93607 and children.
ERROR: Fatal error found, match ERROR-KEYWORD 'Out of Memory'
[13045762.479907] Out of memory: Killed process 19530 (mysqldump).
由于内存不足,系统选择性的选择了耗用内存大的几个进程kill掉了。先kill了mysqld,最后才把mysqldump kill掉,这样有理由怀疑可能是因为mysqldump耗用了大量的内存导致的。
在这个db上,每天凌晨会使用mysqldump做单表备份并通过管道进行压缩。这个备份任务已经部署了超过1年多了。
查看了后台采集的OS性能数据,也可以发现在mysqldump启动直到备份结束,内存耗用会上升比较多,这样可以肯定是因为mysqldump耗用大量内存导致此次故障发生。
check备份使用的脚本,备份的逻辑大概如下:
1:show tables like 'xxx%' 获取需要备份的表名
2:mysqldump --uxx -pyy --skip-opt <dbname>
<tablename> >> <bakfilename>
至此问题就比较清晰了,mysqldump由于未使用-q参数导致耗用内存过大而导致OOM现象发生。
对mysqldump -q参数的解释(取自man mysqldump)
? --quick, -q
This option is useful for dumping large tables. It forces mysqldump to retrieve rows for a table from the server a row at a time rather than retrieving the entire row set and buffering it in memory before writing it out.
这个选项被用来dump比较大的表。它强制mysqldump从服务器一行一行的获取数据而不是把获取所有行的数据在输出之前把它缓存到内存中。
以下是一个测试,可以看到-q 参数对内存耗用的影响:
1:不带-q参数
top输出如下:
PID USER PR NI VIRT RES
SHR S %CPU %MEM TIME+ COMMAND
20010 mysql 15 0 18.0g 17g 4496 S 10
56.6 2765:51 mysqld
27518 mysql 25 0 4227m 4.1g 1048 R 100
13.1 0:33.05 mysqldump
内存耗用超过4G
2:带-q参数
top输出如下:
PID USER PR NI VIRT RES
SHR S %CPU %MEM TIME+ COMMAND
20010 mysql 16 0 18.0g 17g 4496 S 84
56.6 2766:12 mysqld
27686 mysql 25 0 11628 1380 1052 R
98 0.0 0:23.20 mysqldump
内存耗用很小,只有几K
应对方案:
修改备份脚本,加上-q参数。
到此还没完,这个备份任务已经部署了超过1年了,为啥到最近才出现此故障呢?
对DB内的数据做了个统计,需要备份表从之前100M/day的数据量突然爆增到4G/day。知会研发跟进问题,最后发现是前端配置更改导致前端不断重试导致。
体会:
在很多时候,故障的发生是很多因素交织在一起才发生的。碰到问题需要更深一层考虑去探寻问题发生的根本原因。