mysql的恢复过程非常慢

今天同事在没有正常停止mysql5.6服务的情况下，重启了服务器，在启动mysql的时候，进程了recovery，日志如下：
2016-08-10 12:15:24 4401 [Note] InnoDB: Log scan progressed past the checkpoint lsn 255730074061
2016-08-10 12:15:24 4401 [Note] InnoDB: Database was not shutdown normally!
2016-08-10 12:15:24 4401 [Note] InnoDB: Starting crash recovery.
2016-08-10 12:15:24 4401 [Note] InnoDB: Reading tablespace information from the .ibd files…
2016-08-10 12:15:24 4401 [Note] InnoDB: Restoring possible half-written data pages
2016-08-10 12:15:24 4401 [Note] InnoDB: from the doublewrite buffer…
InnoDB: Doing recovery: scanned up to log sequence number 255735316480
InnoDB: Doing recovery: scanned up to log sequence number 255740559360
InnoDB: Doing recovery: scanned up to log sequence number 255745802240
InnoDB: Doing recovery: scanned up to log sequence number 255751045120
InnoDB: Doing recovery: scanned up to log sequence number 255756288000
InnoDB: Doing recovery: scanned up to log sequence number 255761530880
InnoDB: Doing recovery: scanned up to log sequence number 255766773760
InnoDB: Doing recovery: scanned up to log sequence number 255772016640
InnoDB: Doing recovery: scanned up to log sequence number 255777259520
InnoDB: Doing recovery: scanned up to log sequence number 255782502400
InnoDB: Doing recovery: scanned up to log sequence number 255787745280
InnoDB: Doing recovery: scanned up to log sequence number 255792988160
InnoDB: Doing recovery: scanned up to log sequence number 255798231040
InnoDB: Doing recovery: scanned up to log sequence number 255803473920
InnoDB: Doing recovery: scanned up to log sequence number 255808716800
InnoDB: Doing recovery: scanned up to log sequence number 255813959680
InnoDB: Doing recovery: scanned up to log sequence number 255819202560
InnoDB: Doing recovery: scanned up to log sequence number 255824445440
InnoDB: Doing recovery: scanned up to log sequence number 255829688320
InnoDB: Doing recovery: scanned up to log sequence number 255834931200
InnoDB: Doing recovery: scanned up to log sequence number 255840174080
InnoDB: Doing recovery: scanned up to log sequence number 255845416960
InnoDB: Doing recovery: scanned up to log sequence number 255850659840
InnoDB: Doing recovery: scanned up to log sequence number 255855902720
InnoDB: Doing recovery: scanned up to log sequence number 255861145600
InnoDB: Doing recovery: scanned up to log sequence number 255866388480
InnoDB: Doing recovery: scanned up to log sequence number 255871631360
InnoDB: Doing recovery: scanned up to log sequence number 255876874240
InnoDB: Doing recovery: scanned up to log sequence number 255882117120
InnoDB: Doing recovery: scanned up to log sequence number 255887360000
InnoDB: Doing recovery: scanned up to log sequence number 255892602880
InnoDB: Doing recovery: scanned up to log sequence number 255897845760
InnoDB: Doing recovery: scanned up to log sequence number 255903088640
InnoDB: Doing recovery: scanned up to log sequence number 255908331520
InnoDB: Doing recovery: scanned up to log sequence number 255913574400
InnoDB: Doing recovery: scanned up to log sequence number 255918817280
…………………..
InnoDB: Doing recovery: scanned up to log sequence number 256479805440
InnoDB: Doing recovery: scanned up to log sequence number 256481720592
2016-08-10 12:17:02 4401 [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 48 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: Apply batch completed
InnoDB: Last MySQL binlog file position 0 859934940, file name mysql-bin.000081
2016-08-10 12:38:28 4401 [Note] InnoDB: 128 rollback segment(s) are active.
2016-08-10 12:38:28 4401 [Note] InnoDB: Waiting for purge to start
2016-08-10 12:38:28 4401 [Note] InnoDB: 5.6.21 started; log sequence number 256481720592
2016-08-10 12:38:28 4401 [Note] Recovering after a crash using mysql-bin
2016-08-10 12:38:35 4401 [Note] Starting crash recovery…
2016-08-10 12:38:35 4401 [Note] Crash recovery finished.
2016-08-10 12:38:36 4401 [Note] RSA private key file not found: /data/mysql_3306//private_key.pem. Some authentication plugins will not work.
2016-08-10 12:38:36 4401 [Note] RSA public key file not found: /data/mysql_3306//public_key.pem. Some authentication plugins will not work.
2016-08-10 12:38:36 4401 [Note] Server hostname (bind-address): ‘*’; port: 3306
2016-08-10 12:38:36 4401 [Note] IPv6 is available.
2016-08-10 12:38:36 4401 [Note] - ‘::’ resolves to ‘::’;
2016-08-10 12:38:36 4401 [Note] Server socket created on IP: ‘::’.
2016-08-10 12:38:36 4401 [Warning] ‘user’ entry ‘@zabbix’ ignored in –skip-name-resolve mode.
2016-08-10 12:38:36 4401 [Note] Event Scheduler: Loaded 0 events
2016-08-10 12:38:36 4401 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: ‘5.6.21-log’ socket: ‘/tmp/mysql3306.sock’ port: 3306 Source distribution

这个恢复的时间非常长，为什么mysql需要这么长的时间来恢复，按常理说他只需要读取部分的redo log应用即可。下面是mysql server blog中的描述
The InnoDB redo log is referring to tablespaces by a number, space_id, while the file system knows the tablespaces as tablename.ibd. If InnoDB startup notices that the system was not shut down cleanly (there were some log records written since the latest log checkpoint), it will have to construct a mapping from space_id to file names, so that the redo log records can be replayed to compensate for the missing writes of modified pages from the buffer pool to the files.

To construct this mapping, InnoDB used to traverse the data directory, reading the first pages of all *.ibd files. This can cause a lot of unnecessary downtime when only a few files were modified since the latest log checkpoint. There could be thousands of files.

When MySQL 5.6 implemented the DATA DIRECTORY clause for InnoDB tables, it introduced .isl files as placeholders, pointing to the real location of .ibd files. This added further complexity to the tablespace file discovery.
在5.7上有了改进
MySQL 5.7 introduces a new redo log record type MLOG_FILE_NAME for identifying those non-predefined files that were changed since the latest log checkpoint. To avoid growing the volume of the redo log, only one record will be emitted for each tablespace that was modified since the latest checkpoint.

This change narrowly missed the MySQL 5.7.4 milestone release. It is included in the MySQL Labs Release based on 5.7.4. Note that this will change the redo log format, making upgrades and downgrades impossible unless the system was shut down cleanly before upgrading or downgrading.

The objective of this change is to eliminate the use of the file system as a ‘data dictionary’ during redo log processing (before applying redo log):

Do not read the first page of all $datadir//.ibd files
Do not check the contents of $datadir//.isl files

关于mysql恢复过程很慢的原因，记得还有一篇文章是说在恢复的过程中没有使用并行
https://www.percona.com/blog/2014/12/24/innodb-crash-recovery-speed-mysql-5-6/