令人崩溃的mysql崩溃恢复过程

1. 故障说明

接到告警,由于把/data文件系统用满,导致mysqld进程宕掉,无法启动。这台mysql数据库是单机,无复制

# df -h
Filesystem                           Size  Used Avail Use% Mounted on
/dev/mapper/vg_xxxxxxx-LogVol00       20G  440M   19G   3% /
tmpfs                                127G  224K  127G   1% /dev/shm
/dev/sda1                            194M   36M  149M  20% /boot
/dev/mapper/vg_xxxxxxx-LogVol01       50G   43G  4.6G  91% /home
/dev/mapper/vg_xxxxxxx-LogVol05       20G  172M   19G   1% /opt
/dev/mapper/vg_xxxxxxx-LogVol02       50G  180M   47G   1% /tmp
/dev/mapper/vg_xxxxxxx-LogVol03       20G  7.7G   12G  41% /usr
/dev/mapper/vg_xxxxxxx-LogVol04       50G  599M   47G   2% /var
/dev/mapper/datavg-lvol0             4.3T  4.1T   18M 100% /data
/dev/mapper/vg_xxxxxxx-lv_mysqldata  197G  188M  187G   1% /mysqldata

在/data目录中找到几个mysql的bin日志,移到其它目录后释放出800M左右的空间。重启mysql进程

2. 重启mysql服务

# service mysqld start
Starting MySQL (Percona Server)...................................................................................................................................
..................................................................................................................................................................
..................................................................................................................................................................
..................................................................................................................................................................
..................................................................................................................................................................
.....................................................................[FAILED]............................................

启动mysql服务的时间很长,超过半小时,最后失败。其实过了10分钟,就紧张了,担心不会起不来吧。
观察mysql的日志发现:

 161107 12:28:15 mysqld_safe Starting mysqld daemon with databases from /data/mysql/mysql/data
 2016-11-07 12:28:16 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
 2016-11-07 12:28:16 0 [Note] /data/mysql/mysql/bin/mysqld (mysqld 5.6.25-73.1-log) starting as process 135805 ...
 2016-11-07 12:28:16 135805 [Note] Plugin 'FEDERATED' is disabled.
 2016-11-07 12:28:16 135805 [Note] InnoDB: Using atomics to ref count buffer pool pages
 2016-11-07 12:28:16 135805 [Note] InnoDB: The InnoDB memory heap is disabled
 2016-11-07 12:28:16 135805 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 2016-11-07 12:28:16 135805 [Note] InnoDB: Memory barrier is not used
 2016-11-07 12:28:16 135805 [Note] InnoDB: Compressed tables use zlib 1.2.3
 2016-11-07 12:28:16 135805 [Note] InnoDB: Using Linux native AIO
 2016-11-07 12:28:16 135805 [Note] InnoDB: Using CPU crc32 instructions
 2016-11-07 12:28:16 135805 [Note] InnoDB: Initializing buffer pool, size = 20.0G
 2016-11-07 12:28:17 135805 [Note] InnoDB: Completed initialization of buffer pool
 2016-11-07 12:28:17 135805 [Note] InnoDB: Highest supported file format is Barracuda.
 2016-11-07 12:28:17 135805 [Note] InnoDB: Log scan progressed past the checkpoint lsn 28028317998359
 2016-11-07 12:28:17 135805 [Note] InnoDB: Database was not shutdown normally!
 2016-11-07 12:28:17 135805 [Note] InnoDB: Starting crash recovery.
 2016-11-07 12:28:17 135805 [Note] InnoDB: Reading tablespace information from the .ibd files...
 2016-11-07 12:28:17 135805 [Note] InnoDB: Restoring possible half-written data pages
 2016-11-07 12:28:17 135805 [Note] InnoDB: from the doublewrite buffer...
 InnoDB: Doing recovery: scanned up to log sequence number 28028323240960
 InnoDB: Doing recovery: scanned up to log sequence number 28028328483840
 InnoDB: Doing recovery: scanned up to log sequence number 28028333726720
 ......
 InnoDB: Doing recovery: scanned up to log sequence number 28029020544000
 InnoDB: Doing recovery: scanned up to log sequence number 28029025786880
 InnoDB: Doing recovery: scanned up to log sequence number 28029031029760
 InnoDB: Doing recovery: scanned up to log sequence number 28029036272640
 InnoDB: Doing recovery: scanned up to log sequence number 28029041515520
 InnoDB: Doing recovery: scanned up to log sequence number 28029046758400
 InnoDB: Doing recovery: scanned up to log sequence number 28029052001280
 InnoDB: Doing recovery: scanned up to log sequence number 28029057244160
 InnoDB: Doing recovery: scanned up to log sequence number 28029062487040
 InnoDB: Doing recovery: scanned up to log sequence number 28029067729920
 InnoDB: Doing recovery: scanned up to log sequence number 28029070169225

日志一直停留在InnoDB: Doing recovery,没有其它报错。

3. strace跟踪

由于不知道mysqld进程到底在执行什么,这里使用strace跟踪mysqld进程

# ps -ef | grep mysqld
root     132102 131974  0 11:21 pts/9    00:00:00 tail -200f mysqld.log
root     135262      1  0 12:28 pts/8    00:00:00 /bin/sh /data/mysql/mysql/bin/mysqld_safe --datadir=/data/mysql/mysql/data --pid-file=/data/mysql/mysql/mysqld.pid
mysql    135805 135262 38 12:28 pts/8    00:12:09 /data/mysql/mysql/bin/mysqld --basedir=/data/mysql/mysql --datadir=/data/mysql/mysql/data --plugin-dir=/data/mysql/mysql/lib/mysql/plugin --user=mysql --log-error=/data/mysql/mysql/mysqld.log --pid-file=/data/mysql/mysql/mysqld.pid --socket=/var/lib/mysql/mysql.sock --port=3306
root     136851 136760  0 12:35 pts/15   00:00:00 tail -100f mysqld.log
root     137877 133650  0 13:00 pts/11   00:00:00 grep mysqld
# strace -p 135805 2>&1|grep -v time | more
Process 135805 attached - interrupt to quit
pread(4, "\236>^\205\0a\374}\0\0\0\0\0\0\0\0\0\0\30\271[4\316\301\0\2\0\0\0\0\0\0"..., 16384, 105211969536) = 16384
pread(4, "\276Qr\350\0a\374|\0\0\0\0\0\0\0\0\0\0\30\271[3\304\267\0\2\0\0\0\0\0\0"..., 16384, 105211953152) = 16384
pread(4, "\214\200\257d\0a\374{\0\0\0\0\0\0\0\0\0\0\30\271[2I'\0\2\0\0\0\0\0\0"..., 16384, 105211936768) = 16384
pread(4, "\261\311!\313\0a\374z\0\0\0\0\0\0\0\0\0\0\30\271[.r\233\0\2\0\0\0\0\0\0"..., 16384, 105211920384) = 16384
pread(4, "K\2\"\330\0a\374y\0\0\0\0\0\0\0\0\0\0\30\271[-\0346\0\2\0\0\0\0\0\0"..., 16384, 105211904000) = 16384
pread(4, "xS\"_\0a\374x\0\0\0\0\0\0\0\0\0\0\30\271[,&n\0\2\0\0\0\0\0\0"..., 16384, 105211887616) = 16384
pread(4, "9\241\370\254\0a\374w\0\0\0\0\0\0\0\0\0\0\30\271[+c\6\0\2\0\0\0\0\0\0"..., 16384, 105211871232) = 16384
pread(4, "^\337Q\247\0a\374v\0\0\0\0\0\0\0\0\0\0\30\271[*\224I\0\2\0\0\0\0\0\0"..., 16384, 105211854848) = 16384
pread(4, "\300w\244\212\0a\374u\0\0\0\0\0\0\0\0\0\0\30\271[)p\273\0\2\0\0\0\0\0\0"..., 16384, 105211838464) = 16384
......

这里发现mysqld正在执行pread的系统调用,所以判断mysqld进程应该没有死掉。
查了下man手册,pread这个系统调用是读写文件描述符的。

# man pread
PREAD(2)                   Linux Programmer’s Manual                  PREAD(2)

NAME
       pread, pwrite - read from or write to a file descriptor at a given offset

SYNOPSIS
       #define _XOPEN_SOURCE 500

       #include <unistd.h>

       ssize_t pread(int fd, void *buf, size_t count, off_t offset);

       ssize_t pwrite(int fd, const void *buf, size_t count, off_t offset);

pread系统调用函数的第一个参数是文件句柄。这个可以在/proc中观察到

# cd /proc/135805/fd
# ls -lrt
total 0
l-wx------. 1 root root 64 Nov  7 12:28 2 -> /data/mysql/mysql/mysqld.log
lrwx------. 1 root root 64 Nov  7 13:04 9 -> /data/mysql/mysql/data/ib_logfile0
lrwx------. 1 root root 64 Nov  7 13:04 8 -> /tmp/ibVPlMHw (deleted)
lrwx------. 1 root root 64 Nov  7 13:04 7 -> /tmp/ib1B5EQN (deleted)
lrwx------. 1 root root 64 Nov  7 13:04 6 -> /tmp/ibadyWJX (deleted)
lrwx------. 1 root root 64 Nov  7 13:04 5 -> /tmp/ib1ULfD7 (deleted)
lrwx------. 1 root root 64 Nov  7 13:04 4 -> /data/mysql/mysql/data/ibdata1     --> mysql正在读这个文件
lrwx------. 1 root root 64 Nov  7 13:04 3 -> /data/mysql/mysql/data/mysql-bin.index
lrwx------. 1 root root 64 Nov  7 13:04 13 -> /tmp/ibHeC0Wq (deleted)
lrwx------. 1 root root 64 Nov  7 13:04 11 -> /data/mysql/mysql/data/bigdatadb/ta_call_frd_ccl_user_m#P#p201605.ibd
lrwx------. 1 root root 64 Nov  7 13:04 10 -> /data/mysql/mysql/data/ib_logfile1
l-wx------. 1 root root 64 Nov  7 13:04 1 -> /data/mysql/mysql/mysqld.log
lr-x------. 1 root root 64 Nov  7 13:04 0 -> /dev/null

# ls -lh /data/mysql/mysql/data/ibdata1
-rw-rw----. 1 mysql mysql 255G Nov  7 11:05 /data/mysql/mysql/data/ibdata1

ibdata1这个文件非常大,这个文件具体有什么作用,参考:
为什么 mysql 里的 ibdata1 文件不断的增长?
MySQL 5.6 如何给ibdata1瘦身
用strace跟踪mysqld进程发现,扫描ibdata1这个文件的时间超过了1.5小时。扫描完成后,mysql进入了恢复阶段,后面的日志如下:

InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 3677M row operations to undo
InnoDB: Trx id counter is 41274112
2016-11-07 14:28:09 135805 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 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 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 4
 8 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 

--> 在InnoDB: Progress in percent阶段耗时也很长,超过2小时

InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 16660612, file name mysql-bin.006970
2016-11-07 16:23:24 135805 [Note] InnoDB: 128 rollback segment(s) are active.
InnoDB: Starting in background the rollback of uncommitted transactions
2016-11-07 16:23:24 7f7df1bff700  InnoDB: Rolling back trx with id 41113654, 3677M rows to undo

InnoDB: Progress in percents: 12016-11-07 16:23:24 135805 [Note] InnoDB: Waiting for purge to start
2016-11-07 16:23:24 135805 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.25-rel73.1 started; log sequence number 28029070169225
2016-11-07 16:23:24 135805 [Note] Recovering after a crash using mysql-bin
2016-11-07 16:23:24 135805 [ERROR] Error in Log_event::read_log_event(): 'read error', data_len: 556, event_type: 2
2016-11-07 16:23:24 135805 [Note] Starting crash recovery...
2016-11-07 16:23:24 135805 [Note] Crash recovery finished.
2016-11-07 16:23:24 135805 [Note] Crashed binlog file ./mysql-bin.006970 size is 16650240, but recovered up to 16649829. Binlog trimmed to 16649829 bytes.
/data/mysql/mysql/bin/mysqld: File './mysql-bin.006969' not found (Errcode: 2 - No such file or directory)
2016-11-07 16:23:24 135805 [ERROR] Failed to open log (file './mysql-bin.006969', errno 2)
2016-11-07 16:23:24 135805 [ERROR] Could not open log file
2016-11-07 16:23:24 135805 [Note] RSA private key file not found: /data/mysql/mysql/data//private_key.pem. Some authentication plugins will not work.
2016-11-07 16:23:24 135805 [Note] RSA public key file not found: /data/mysql/mysql/data//public_key.pem. Some authentication plugins will not work.
2016-11-07 16:23:24 135805 [Note] Server hostname (bind-address): '*'; port: 3306
2016-11-07 16:23:24 135805 [Note] IPv6 is available.
2016-11-07 16:23:24 135805 [Note]   - '::' resolves to '::';
2016-11-07 16:23:24 135805 [Note] Server socket created on IP: '::'.
2016-11-07 16:23:25 135805 [Warning] 'user' entry 'root@xxxxxxx' ignored in --skip-name-resolve mode.
2016-11-07 16:23:25 135805 [Warning] 'user' entry '@xxxxxxx' ignored in --skip-name-resolve mode.
2016-11-07 16:23:25 135805 [Warning] 'user' entry 'reply@test-1' ignored in --skip-name-resolve mode.
2016-11-07 16:23:25 135805 [Warning] 'user' entry 'reply@test-2' ignored in --skip-name-resolve mode.
2016-11-07 16:23:25 135805 [Warning] 'proxies_priv' entry '@ root@xxxxxxx' ignored in --skip-name-resolve mode.
2016-11-07 16:23:25 135805 [Warning] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. P
lease consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.
2016-11-07 16:23:25 135805 [Warning] Slave SQL: If a crash happens this configuration does not guarantee that the relay log info will be consistent, Error_code: 0
2016-11-07 16:23:25 135805 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000051' at position 1051509599, relay log './mysqld-relay-bin
.000155' position: 4
2016-11-07 16:23:25 135805 [ERROR] Slave I/O: error connecting to master 'reply@xxx.xxx.xx.132:3306' - retry-time: 60  retries: 1, Error_code: 1130
2016-11-07 16:23:25 135805 [Note] Event Scheduler: Loaded 3 events
2016-11-07 16:23:25 135805 [Note] /data/mysql/mysql/bin/mysqld: ready for connections.
Version: '5.6.25-73.1-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  Percona Server (GPL), Release 73.1, Revision 07b797f

整个崩溃恢复过程结束后,顺利打开了mysql数据库,整个MySQL启动过程用时超过4.5小时,这也太变态了……

关于紫砂壶

感悟技术人生
此条目发表在MySQL分类目录,贴了标签。将固定链接加入收藏夹。