MySQL5.1 vs 5.5 宕机恢复时间对比，5.5快18倍。

squall

作者：squall（贺春旸）， 出处：mysqlpub.com，转载请注明。

5.1 vs 5.5 宕机恢复时间对比

sysbench参数（两边均一致）

1. sysbenc --test=oltp
   
2. --mysql-table-engine=innodb
   
3. --oltp-table-size=10000000
   
4. --max-requests=90000000
   
5. --num-threads=200
   
6. --mysql-host=192.168.110.218
   
7. --mysql-port=3306
   
8. --mysql-user=admin
   
9. --mysql-password=123456
   
10. --mysql-db=test
    
11. --mysql-socket=/tmp/mysql.sock run

复制代码

200个并发连接，最大请求数9千万个（查询、更新、查询、修改），表的记录数1千万。

my.cnf参数（两边均一致）

1. innodb_buffer_pool_size = 11G
   
2. innodb_log_file_size = 1024M
   
3. innodb_flush_log_at_trx_commit = 0
   
4. innodb_max_dirty_pages_pct = 75

复制代码

1. sleep 900;pkill -9 mysqld

复制代码

900秒后，强杀mysql进程，以下是恢复时间：

MySQL5.1，耗时18分29秒。

130305 15:38:07  InnoDB: Database was not shut down normally! InnoDB: Starting crash recovery. InnoDB: Reading tablespace information from the .ibd files... InnoDB: Restoring possible half-written data pages from the doublewrite InnoDB: buffer... InnoDB: Doing recovery: scanned up to log sequence number 2 1438088704 InnoDB: Doing recovery: scanned up to log sequence number 2 1443331584 InnoDB: Doing recovery: scanned up to log sequence number 2 1448574464 InnoDB: Doing recovery: scanned up to log sequence number 2 1453817344 InnoDB: Doing recovery: scanned up to log sequence number 2 1459060224 InnoDB: Doing recovery: scanned up to log sequence number 2 1464303104 ...... InnoDB: Doing recovery: scanned up to log sequence number 2 2481421824 InnoDB: Doing recovery: scanned up to log sequence number 2 2486664704 InnoDB: Doing recovery: scanned up to log sequence number 2 2490245486 130305 15:50:26  InnoDB: Starting an apply batch of log records to the database... InnoDB: Progress in percents: 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 31260491, file name /home/mysql/mysql-5.1.43sp1/data.000010 130305 15:56:35  InnoDB: Started; log sequence number 2 2490245486 130305 15:56:35 [Note] Recovering after a crash using /home/mysql/mysql-5.1.43sp1/data 130305 15:56:36 [Note] Starting crash recovery... 130305 15:56:36 [Note] Crash recovery finished. 130305 15:56:36 [Warning] 'user' entry 'root@TestMonServer' ignored in --skip-name-resolve mode. 130305 15:56:36 [Warning] 'user' entry '@TestMonServer' ignored in --skip-name-resolve mode. 130305 15:56:36 [Note] Event Scheduler: Loaded 0 events 130305 15:56:36 [Note] /home/mysql/mysql-5.1.43sp1/bin/mysqld: ready for connections. Version: '5.1.43sp1-enterprise-gpl-pro-log'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Enterprise Server - Pro Edition (GPL) 130305 15:56:36 [Note] Event Scheduler: scheduler thread started with id 1

MySQL5.5，耗时1分17秒。

130305 17:09:12  InnoDB: Database was not shut down normally! InnoDB: Starting crash recovery. InnoDB: Reading tablespace information from the .ibd files... InnoDB: Restoring possible half-written data pages from the doublewrite InnoDB: buffer... InnoDB: Doing recovery: scanned up to log sequence number 18163911680 InnoDB: Doing recovery: scanned up to log sequence number 18169154560 InnoDB: Doing recovery: scanned up to log sequence number 18174397440 InnoDB: Doing recovery: scanned up to log sequence number 18179640320 InnoDB: Doing recovery: scanned up to log sequence number 18184883200 InnoDB: Doing recovery: scanned up to log sequence number 18190126080 ...... InnoDB: Doing recovery: scanned up to log sequence number 18588584960 InnoDB: Doing recovery: scanned up to log sequence number 18593827840 InnoDB: Doing recovery: scanned up to log sequence number 18596304961 InnoDB: 65 transaction(s) which must be rolled back or cleaned up InnoDB: in total 167 row operations to undo InnoDB: Trx id counter is A19B00 130305 17:09:58  InnoDB: Starting an apply batch of log records to the database... InnoDB: Progress in percents: 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 83569404, file name /home/mysql/mysql-5.5.20/data.000031 InnoDB: Starting in background the rollback of uncommitted transactions 130305 17:10:26  InnoDB: Rolling back trx with id A19952, 1 rows to undo 130305 17:10:26  InnoDB: Waiting for the background threads to start InnoDB: Rolling back of trx id A19952 completed 130305 17:10:26  InnoDB: Rolling back trx with id A19941, 1 rows to undo InnoDB: Rolling back of trx id A19941 completed 130305 17:10:26  InnoDB: Rolling back trx with id A1993A, 4 rows to undo InnoDB: Rolling back of trx id A1993A completed 130305 17:10:26  InnoDB: Rolling back trx with id A19938, 4 rows to undo InnoDB: Rolling back of trx id A19938 completed 130305 17:10:26  InnoDB: Rolling back trx with id A19935, 1 rows to undo ...... InnoDB: Rolling back of trx id A19737 completed 130305 17:10:27  InnoDB: Rolling back trx with id A19729, 1 rows to undo InnoDB: Rolling back of trx id A19729 completed 130305 17:10:27  InnoDB: Rolling back trx with id A19719, 5 rows to undo InnoDB: Rolling back of trx id A19719 completed 130305 17:10:27  InnoDB: Rolling back trx with id A1970D, 1 rows to undo InnoDB: Rolling back of trx id A1970D completed 130305 17:10:27  InnoDB: Rollback of non-prepared transactions completed 130305 17:10:27 InnoDB: 1.1.8 started; log sequence number 18596304961 130305 17:10:27 [Note] Recovering after a crash using /home/mysql/mysql-5.5.20/data 130305 17:10:29 [Note] Starting crash recovery... 130305 17:10:29 [Note] Crash recovery finished. 130305 17:10:29 [Warning] 'user' entry 'root@TestMonServer' ignored in --skip-name-resolve mode. 130305 17:10:29 [Warning] 'user' entry '@TestMonServer' ignored in --skip-name-resolve mode. 130305 17:10:29 [Warning] 'proxies_priv' entry '@ root@TestMonServer' ignored in --skip-name-resolve mode. 130305 17:10:29 [Note] Event Scheduler: Loaded 0 events 130305 17:10:29 [Note] /home/mysql/mysql-5.5.20/bin/mysqld: ready for connections. Version: '5.5.20-enterprise-commercial-advanced-log'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Enterprise Server - Advanced Edition (Commercial) 130305 17:10:29 [Note] Event Scheduler: scheduler thread started with id 1

结论：5.5比5.1恢复时间快了18倍。

回顾：MySQL Conference & Expo，当时InnoDB1.0.7GA(with MySQL-5.5)的新特性公布抢尽了风头，回头想想，Oracle/InnoDB也是酝酿已久吧。回想起来，InnoDB的Faster Recovery特性着实值得关注。

想尽一切办法缩短MySQL的不可用时间，仍然是DBA的目标。根据经验，主机OS崩溃、硬件故障，仍然是影响MySQL可用性的最主要因素，当这些故障(OS、硬件)恢复后，另一个非常耗时的恢复就是InnoDB自己的恢复时间。一般主机发生一次重启，正常大约小于5分钟，但此时 InnoDB恢复可能需要40分钟或者更久(这依赖于Buffer Pool、脏页面比例、TPS等因素)。试想，如果每次能够把故障时间控制在10分钟之内，那么通过应用容错、Cache支持等办法，用户体验和可用时间都将有进一步的提升。而Plugin1.0.7GA通过算法和内存管理上的改进，将crash recovery大大缩短了，这也就意味着以后redo log可以顶着4G用了(xtraDB可以超过4G)，这样可以在很大程度上降低IO需求、从而极大地提高InnoDB的写性能。