(转）625某电商网站数据库宕机故障解决实录（上）

625某电商网站数据库特大故障解决实录(上)

 原文：http://oldboy.blog.51cto.com/2561410/1431161

这是一次，惊心动魄的企业级电商网站数据库在线故障解决实录，故障解决的过程遇到了很多问题，思想的碰撞，解决方案的决策，及实际操作的问题困扰，老男孩尽量原汁原味的描述恢复的全部过程及思想思维过程！老男孩教育版权所有，本内容禁止商业用途。

目录：

625某电商网站数据库特大故障解决实录... 1

1接到电商客户报警... 1

1.1与客户初步沟通... 1

1.2深入沟通确定故障恢复方案... 2

1.3开始故障恢复准备... 4

1.4开始进行故障恢复*****. 6

1.5数据库故障恢复后扫尾工作... 15

1接到电商客户报警

1.1与客户初步沟通

昨日接到某电商网站客户电话，说搞秒杀赠送活动，数据库遇到问题了，结果启动起不来了。

1 2	[root@etiantian etc]# /etc/init.d/mysqld start Starting MySQL. ERROR! The server quit without updating PID file (/var/run/mysqld/mysqld.pid).

提示：此部分客户给的是截图，是后期老男孩根据SSH日志整理而来。

由于时间紧急，本能的提示客户看看/var/run/mysqld/mysqld.pid存在否，如果存在，删除再启动，客户说没有这个PID文件，提示用户用mysqld_safe --user=mysql &启动看看，结果可以启动成功done，但是，端口服务依然起不来。让客户查下mysql启动日志，报错如下：

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25

[root@etiantian etc]# cat /var/log/mysqld.log 140624 18:51:58 mysqld_safe Starting mysqld daemon with databases from /data/mysql/ 140624 18:51:58 InnoDB: The InnoDB memory heap is disabled 140624 18:51:58 InnoDB: Mutexes and rw_locks use GCC atomic builtins 140624 18:51:58 InnoDB: Compressed tables use zlib 1.2.3 140624 18:51:58 InnoDB: Initializing buffer pool, size = 768.0M 140624 18:51:58 InnoDB: Completed initialization of buffer pool InnoDB: Error: auto-extending data file ./ibdata1 is of a different size InnoDB: 2176 pages (rounded down to MB) than specified in the .cnf file: InnoDB: initial 65536 pages, max 0 (relevant if non-zero) pages! 140624 18:51:58 InnoDB: Could not open or create data files. 140624 18:51:58 InnoDB: If you tried to add new data files, and it failed here, 140624 18:51:58 InnoDB: you should now edit innodb_data_file_path in my.cnf back 140624 18:51:58 InnoDB: to what it was, and remove the new ibdata files InnoDB created 140624 18:51:58 InnoDB: in this failed attempt. InnoDB only wrote those files full of 140624 18:51:58 InnoDB: zeros, but did not yet use them in any way. But be careful: do not 140624 18:51:58 InnoDB: remove old data files which contain your precious data! 140624 18:51:58 [ERROR] Plugin 'InnoDB' init function returned error. 140624 18:51:58 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed. 140624 18:51:58 [ERROR] Unknown/unsupported storage engine: InnoDB 140624 18:51:58 [ERROR] Aborting    140624 18:51:58 [Note] /install/mysql/bin/mysqld: Shutdown complete    140624 18:51:58 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended

提示：此部分客户给的是截图，是后期老男孩根据SSH日志整理而来。

红色部分为错误。
InnoDB: Error: auto-extending data file ./ibdata1 is of a different size140624 18:51:58 [ERROR] Plugin 'InnoDB' init function returned error.
140624 18:51:58 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
140624 18:51:58 [ERROR] Unknown/unsupported storage engine: InnoDB
140624 18:51:58 [ERROR] Aborting

根据客户的信息和自身的经验基本定位了客户有可能强制终止了进程或者改变了数据文件！

于是，询问客户故障前和故障后，都做了啥操作，得到的回答如下：

1 2 3 4 5 6

XXXX 18:53:41  数据库之前停止响应，killall之前已经没办法做restart重启了 XXXX 18:53:32 我觉得有问题，然后killall掉了，然后就起不来了，别的没做。 根据日志以及客户的描述，基本上断定是强制关闭服务导致innodb表空间或文件异常。 至此问题原因及故障现象已经确定。

1.2深入沟通确定故障恢复方案

由于客户比较着急，人很紧张，且恢复网站提供服务迫在眉睫，老板就在旁边紧盯着客户。。，压力比较大，因此，客户要求老男孩项目团队远程连接介入，代为操作解决。

和客户确认了责任和风险后！

立即连接服务器，着手进行了一系列的抢救措施，没有结果。抢救措施有：

1、杀掉服务重启。2.调整my.cnf相关参数发现某些参数比较大，特别innodb_buffer，调整后依然无法启动。3.调整innodby recover参数。

由于此前就知道客户是近期刚上线的一个电商网站业务。

因此和客户沟通。询问客户是否有全量备份及增量备份？得到的回答是客户做了全量备份了。增量没做任何处理。

问完了客户，我们自己登陆服务器检查客户提供的信息看看是否都是正确的。

由于时间极其紧迫，客户比较慌张，很多内容自己无法一下说清楚，和老男孩团队又不在一个城市。

于是我们直接登录服务器，根据常规判断及历史记录（history命令行及/root/.mysql_history文件）找到数据库的配置文件/etc/my.cnf，进而找到了数据库安装路径/install/mysql，数据文件路径/data/mysql。binlog的路径/data/mysql，db备份路径/home/xx/。

此时急需要确定的是两件事：第一个就是binlog是否完整，第二个就是全备是否有效。于是根据客户描述以及我们自己登陆服务器查看，结果如下。

第一个binlog数据内容：

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16

<span style="font-size:16px;"><span style="font-family:'宋体';font-size:16px;">[root@etiantianmysql]# ll total118576 -rw-rw----1 mysql mysql 356515840 Jun 24 18:33 ibdata1 -rw-rw----1 mysql mysql  5242880 Jun 24 18:33ib_logfile0 -rw-rw----1 mysql mysql  5242880 Jun 24 18:33ib_logfile1 drwx------2 mysql mysql     4096 Jun 18 16:39 mysql ...... -rw-rw----1 mysql mysql      126 May 21 10:24mysql-bin.000012 -rw-rw---- 1 mysql mysql 1356022 May 21 10:35 mysql-bin.000013 -rw-rw---- 1 mysql mysql 14935771 Jun 18 16:35mysql-bin.000014 -rw-rw---- 1 mysql mysql 56588034 Jun 24 18:33mysql-bin.000015 -rw-rw----1 mysql mysql      285 Jun 18 16:39mysql-bin.index drwx------2 mysql mysql     4096 May 20 21:22performance_schema drwx------2 mysql mysql    20480 May 21 10:28eshop_ett drwx------2 mysql mysql    12288 Jun 18 13:53eshop_ett100 drwx------2 mysql mysql     4096 May 20 21:13 test</span></span>

根据上述结果，确定binlog内容是正常的。

开始查看数据库的全备是不是OK的。

1 2	[root@etiantian backup]# ll /home/xxx/eshop_ett100.0624.sql  -rw-r--r-- 1 root root 55769500 Jun 24 02:21 /home/xxx/eshop_ett100.0624.sql

结论：全备也是OK的。而且，根据binlog日志的时间以及全备的时间看，数据是对应的。

实际调查完毕后，和客户进行沟通恢复方案：

1、如果继续修复数据文件可能时间会比较长，暂时还没头绪。因此，询问客户是不是尽快恢复数据库服务非常重要？得到的答复：“是”。

由于客户非常着急恢复网站业务（活动广告早都打出去了），也就是立刻提供服务非常重要，但是作为一个DBA来讲，数据也是同样重要的。

于是老男孩和客户紧急沟通，给出了一个解决方案：由于当时事情紧急，内容简化，原话如下：

根据你们业务刚上线不久，数据量不是很大，比较好的故障解决方案，就是重建数据库，然后导入备份及增量！我预计整个恢复时间大约10-30分钟左右，数据基本可以做到0损失。也就是说数据不会丢失，最快10分钟可提供服务。

客户对这个方案的回复是：“很满意”，立刻爽快的答应了我们的数据库故障解决方案。原文如下：

1 2 3 4

xxx 19:10:09 你说的我都同意 老男孩 19:10:15  那我开整了

1.3开始故障恢复准备

1、关闭web服务

目的：关闭web的考虑是，防止数据库启动后恢复前用户写入脏数据。

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25

[root@etiantian data]# ps -ef|grep httpd root     28697     1  0 19:15 ?        00:00:00 /install/httpd//bin/httpd -k start www      28699 28697  1 19:15 ?        00:00:02 /install/httpd//bin/httpd -k start www      28702 28697  0 19:15 ?        00:00:00 /install/httpd//bin/httpd -k start www      28703 28697  0 19:15 ?        00:00:00 /install/httpd//bin/httpd -k start www      28704 28697  0 19:15 ?        00:00:00 /install/httpd//bin/httpd -k start www      28707 28697  0 19:15 ?        00:00:00 /install/httpd//bin/httpd -k start www      28709 28697  0 19:15 ?        00:00:00 /install/httpd//bin/httpd -k start www      28711 28697  0 19:15 ?        00:00:00 /install/httpd//bin/httpd -k start www      28712 28697  0 19:15 ?        00:00:00 /install/httpd//bin/httpd -k start www      28713 28697  0 19:15 ?        00:00:00 /install/httpd//bin/httpd -k start www      28714 28697  0 19:15 ?        00:00:00 /install/httpd//bin/httpd -k start www      28715 28697  0 19:15 ?        00:00:00 /install/httpd//bin/httpd -k start www      28716 28697  0 19:15 ?        00:00:00 /install/httpd//bin/httpd -k start www      28720 28697  0 19:15 ?        00:00:00 /install/httpd//bin/httpd -k start   root     28850 26341  0 19:17 pts/5    00:00:00 grep httpd [root@etiantian data]# /etc/init.d/httpd stop [root@etiantian data]# ps -ef|grep httpd root     28855 26341  0 19:17 pts/5    00:00:00 grep httpd [root@etiantian data]# ps -ef|grep httpd root     28857 26341  0 19:17 pts/5    00:00:00 grep httpd [root@etiantian data]# ps -ef|grep httpd root     28877 26341  0 19:18 pts/5    00:00:00 grep httpd [root@etiantian data]# lsof -i :80

2、备份当前正在跑得所有线上数据库数据

目的：不能对客户的数据进行二次破坏数据

1 2 3 4 5 6

[root@etiantian mysql]# cd ../ [root@etiantian data]# tar zcvf /server/backup/mysql.tar.gz ./mysql/ [root@etiantian data]# cp -ap mysql /server/backup/ [root@etiantian data]# du -sh /server/backup/* 1230M    /server/backup/mysql 150M     /server/backup/mysql.tar.gz

3、确认全备数据是正常的。手动检查查看

目的：验证备份的数据确实是OK的，否则后果不堪设想。

1 2 3 4

[root@etiantian data]# ll /data/eshop_ett100.0624.sql  -rw-r--r-- 1 root root 55769500 Jun 24 19:04 /data/eshop_ett100.0624.sql [root@etiantian data]# less /data/eshop_ett100.0624.sql  -- MySQL dump 10.13  Distrib 5.5.33, for Linux (x86_64)

4、搜集db增量日志

彻底杀掉mysql服务

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23

[root@etiantian data]# killall mysqld mysqld: no process killed [root@etiantian data]# killall mysqld mysqld: no process killed [root@etiantian data]# mv mysql /opt/ [root@etiantian opt]# cd mysql/ [root@etiantian mysql]# ll total 118576  -rw-r----- 1 mysql mysql        0 Jun 24 18:53 AY1405201820416899ebZ.err -rw-rw---- 1 mysql mysql 35651584 Jun 24 18:33 ibdata1 -rw-rw---- 1 mysql mysql  5242880 Jun 24 18:33 ib_logfile0 -rw-rw---- 1 mysql mysql  5242880 Jun 24 18:33 ib_logfile1 drwx------ 2 mysql mysql     4096 Jun 18 16:39 mysql  ...... -rw-rw---- 1 mysql mysql      126 May 21 10:24 mysql-bin.000012 -rw-rw---- 1 mysql mysql  1356022 May 21 10:35 mysql-bin.000013 -rw-rw---- 1 mysql mysql 14935771 Jun 18 16:35 mysql-bin.000014 -rw-rw---- 1 mysql mysql 56588034 Jun 24 18:33 mysql-bin.000015 -rw-rw---- 1 mysql mysql      285 Jun 18 16:39 mysql-bin.index drwx------ 2 mysql mysql     4096 May 20 21:22 performance_schema drwx------ 2 mysql mysql    24576 May 21 10:28 eshop_ett drwx------ 2 mysql mysql    12288 Jun 18 13:53 eshop_ett100 drwx------ 2 mysql mysql     4096 May 20 21:13 test

拷贝增量日志，防止被二次破坏。等待恢复。

1	[root@etiantian mysql]# cp mysql-bin.000014  mysql-bin.000015 /server/backup/