redolog 大小的实验
前言：近日因工作需要，测试postgresql和MySQL在oltp对比测试，因结果差异太多（MySQL测试结果比较差，相同环境），寻求大神帮助，有幸得叶大师和姜大师指点，指出my.cnf配置文件innodb_log_file_size不合理（在以前的资料提示Innodb，redolog大小一般都建议128-512M大小，不然崩溃恢复将会很漫长），redolog越大，checkpoint就越少，tps相对越高，MySQL5.6redolog 大小可以超过4G，下面就测试一下不同redolog大小奔溃恢复时间
测试环境：硬件是VM，系统是centos6.6 4核4G内存，宿主硬盘是Intel SSD，测试表数据为1千万行，测试工具为sysbench0.5版本，测试方法是压力测试工具进行压力测试，然后暴力kill MySQL
跟日志相关参数：
innodb_flush_log_at_trx_commit = 1
innodb_log_buffer_size = 32M
innodb_log_file_size = 4096M（分别测试1G，2G,4G）
innodb_log_files_in_group = 2
innodb_max_dirty_pages_pct = 70
IO性能：因为结果出乎人意料我不得不先把我自己IO能力测试出来
16k随机读写IO，读写比例为：40：60 IOPS=2951
fio -filename=/data/fiotest -direct=1 -rw=randrw -ioengine=libaio -rwmixwrite=60 \
> -bs=16k -size=8G -numjobs=64 -runtime=600 -group_reporting -name=mytest
read : io=27676MB, bw=47231KB/s, iops=2951, runt=600025msec
8k随机读写IO，读写比例为：40：60 IOPS=2951
fio -filename=/data/fiotest -direct=1 -rw=randrw -ioengine=libaio -rwmixwrite=60 \
> -bs=8k -size=8G -numjobs=64 -runtime=600 -group_reporting -name=mytest
write: io=18155MB, bw=30983KB/s, iops=3872, runt=600046msec
4K随机读写IO 读写比例为：40：60 IOPS=3590
fio -filename=/data/fiotest -direct=1 -rw=randrw -ioengine=libaio -rwmixwrite=60 \
> -bs=4k -size=8G -numjobs=64 -runtime=600 -group_reporting -name=mytest
read : io=8416.6MB, bw=14363KB/s, iops=3590, runt=600030msec
【1】测试方法
1.1 创建测试表
./sysbench --mysql-host=192.168.80.106 --mysql-user=sysbench --mysql-password=123456 --mysql-db=sysbench --test=/opt/sysbench/tests/db/oltp.lua --oltp_tables_count=10 --oltp-table-size=1000000 --rand-init=on prepare
1.2 进行测试，其中一个会话在做压力测试，一个会话暴力杀掉MySQL sleep 300; pkill -9 mysqld
./sysbench --mysql-host=192.168.80.106 --mysql-port=3306 --mysql-user=sysbench --mysql-password=123456 --test=/opt/sysbench/tests/db/oltp.lua --oltp_tables_count=10 --oltp-table-size=10000000 --num-threads=64-oltp-read-only=off --report-interval=10 --rand-type=uniform --max-time=1200 --mysql-db=sysbench --max-requests=0 --percentile=99 run
【2】测试结果
2.1 innodb_log_file_size = 1024M
150607 11:29:41 mysqld_safe Starting mysqld daemon with databases from /data/mydata 2015-06-07 11:29:41 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details). 2015-06-07 11:29:41 8144 [Note] Plugin 'FEDERATED' is disabled. 2015-06-07 11:29:41 7f80332d07e0 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator. 2015-06-07 11:29:41 8144 [Note] InnoDB: Using atomics to ref count buffer pool pages 2015-06-07 11:29:41 8144 [Note] InnoDB: The InnoDB memory heap is disabled 2015-06-07 11:29:41 8144 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2015-06-07 11:29:41 8144 [Note] InnoDB: Memory barrier is not used 2015-06-07 11:29:41 8144 [Note] InnoDB: Compressed tables use zlib 1.2.3 2015-06-07 11:29:41 8144 [Note] InnoDB: Using Linux native AIO 2015-06-07 11:29:41 8144 [Note] InnoDB: Using CPU crc32 instructions 2015-06-07 11:29:41 8144 [Note] InnoDB: Initializing buffer pool, size = 2.0G 2015-06-07 11:29:41 8144 [Note] InnoDB: Completed initialization of buffer pool 2015-06-07 11:29:41 8144 [Note] InnoDB: Highest supported file format is Barracuda. 2015-06-07 11:29:41 8144 [Note] InnoDB: Log scan progressed past the checkpoint lsn 3383367251 2015-06-07 11:29:41 8144 [Note] InnoDB: Database was not shutdown normally! 2015-06-07 11:29:41 8144 [Note] InnoDB: Starting crash recovery. 2015-06-07 11:29:41 8144 [Note] InnoDB: Reading tablespace information from the .ibd files... 2015-06-07 11:29:42 8144 [Note] InnoDB: Restoring possible half-written data pages 2015-06-07 11:29:42 8144 [Note] InnoDB: from the doublewrite buffer... InnoDB: Doing recovery: scanned up to log sequence number 3388610048 InnoDB: Doing recovery: scanned up to log sequence number 3393852928 InnoDB: Doing recovery: scanned up to log sequence number 3399095808 InnoDB: Doing recovery: scanned up to log sequence number 3404338688 InnoDB: Doing recovery: scanned up to log sequence number 3409581568 InnoDB: Doing recovery: scanned up to log sequence number 3414824448 InnoDB: Doing recovery: scanned up to log sequence number 3420067328 InnoDB: Doing recovery: scanned up to log sequence number 3425310208 InnoDB: Doing recovery: scanned up to log sequence number 3430553088 InnoDB: Doing recovery: scanned up to log sequence number 3435795968 InnoDB: Doing recovery: scanned up to log sequence number 3441038848 InnoDB: Doing recovery: scanned up to log sequence number 3446281728 InnoDB: Doing recovery: scanned up to log sequence number 3446339459 InnoDB: Transaction 419763 was in the XA prepared state. InnoDB: 4 transaction(s) which must be rolled back or cleaned up InnoDB: in total 4 row operations to undo InnoDB: Trx id counter is 420096 2015-06-07 11:29:43 8144 [Note] InnoDB: Starting an apply batch of log records to the database... InnoDB: Progress in percent: 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 67898783, file name dg6-logbin.000007 2015-06-07 11:29:51 8144 [Note] InnoDB: 128 rollback segment(s) are active. 2015-06-07 11:29:51 8144 [Note] InnoDB: Waiting for purge to start InnoDB: Starting in background the rollback of uncommitted transactions 2015-06-07 11:29:51 7f7f6dde8700 InnoDB: Rolling back trx with id 419767, 1 rows to undo 2015-06-07 11:29:51 8144 [Note] InnoDB: Rollback of trx with id 419767 completed 2015-06-07 11:29:51 7f7f6dde8700 InnoDB: Rolling back trx with id 419764, 1 rows to undo 2015-06-07 11:29:51 8144 [Note] InnoDB: Rollback of trx with id 419764 completed 2015-06-07 11:29:51 7f7f6dde8700 InnoDB: Rolling back trx with id 419762, 2 rows to undo 2015-06-07 11:29:51 8144 [Note] InnoDB: Rollback of trx with id 419762 completed 2015-06-07 11:29:51 7f7f6dde8700 InnoDB: Rollback of non-prepared transactions completed 2015-06-07 11:29:51 8144 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.21-rel70.1 started; log sequence number 3446339459 2015-06-07 11:29:51 8144 [Note] Recovering after a crash using dg6-logbin 2015-06-07 11:29:52 8144 [Note] Starting crash recovery... 2015-06-07 11:29:52 7f80332d07e0 InnoDB: Starting recovery for XA transactions... 2015-06-07 11:29:52 7f80332d07e0 InnoDB: Transaction 419763 in prepared state after recovery 2015-06-07 11:29:52 7f80332d07e0 InnoDB: Transaction contains changes to 1 rows 2015-06-07 11:29:52 7f80332d07e0 InnoDB: 1 transactions in prepared state after recovery 2015-06-07 11:29:52 8144 [Note] Found 1 prepared transaction(s) in InnoDB 2015-06-07 11:29:52 8144 [Note] Crash recovery finished. /opt/app/mysql/bin/mysqld: Found a Gtid_log_event or Previous_gtids_log_event when @@GLOBAL.GTID_MODE = OFF. /opt/app/mysql/bin/mysqld: Found a Gtid_log_event or Previous_gtids_log_event when @@GLOBAL.GTID_MODE = OFF. 2015-06-07 11:29:52 8144 [Note] RSA private key file not found: /data/mydata//private_key.pem. Some authentication plugins will not work. 2015-06-07 11:29:52 8144 [Note] RSA public key file not found: /data/mydata//public_key.pem. Some authentication plugins will not work. 2015-06-07 11:29:52 8144 [Note] Server hostname (bind-address): '*'; port: 3306 2015-06-07 11:29:52 8144 [Note] IPv6 is available. 2015-06-07 11:29:52 8144 [Note] - '::' resolves to '::'; 2015-06-07 11:29:52 8144 [Note] Server socket created on IP: '::'. 2015-06-07 11:29:52 8144 [Warning] 'user' entry 'root@dg1' ignored in --skip-name-resolve mode. 2015-06-07 11:29:52 8144 [Warning] 'proxies_priv' entry '@ root@dg1' ignored in --skip-name-resolve mode. 2015-06-07 11:29:52 8144 [Note] Event Scheduler: Loaded 0 events 2015-06-07 11:29:52 8144 [Note] /opt/app/mysql/bin/mysqld: ready for connections. Version: '5.6.21-70.1-log' socket: '/tmp/mysql.sock' port: 3306 Percona Server (GPL), Release 70.1, Revision 698
看到木有恢复时间才十几秒钟呢
2.2 innodb_log_file_size = 2048M
150607 11:41:29 mysqld_safe Starting mysqld daemon with databases from /data/mydata 2015-06-07 11:41:29 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details). 2015-06-07 11:41:29 9675 [Note] Plugin 'FEDERATED' is disabled. 2015-06-07 11:41:29 7f599fd1c7e0 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator. 2015-06-07 11:41:29 9675 [Note] InnoDB: Using atomics to ref count buffer pool pages 2015-06-07 11:41:29 9675 [Note] InnoDB: The InnoDB memory heap is disabled 2015-06-07 11:41:29 9675 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2015-06-07 11:41:29 9675 [Note] InnoDB: Memory barrier is not used 2015-06-07 11:41:29 9675 [Note] InnoDB: Compressed tables use zlib 1.2.3 2015-06-07 11:41:29 9675 [Note] InnoDB: Using Linux native AIO 2015-06-07 11:41:29 9675 [Note] InnoDB: Using CPU crc32 instructions 2015-06-07 11:41:29 9675 [Note] InnoDB: Initializing buffer pool, size = 2.0G 2015-06-07 11:41:30 9675 [Note] InnoDB: Completed initialization of buffer pool 2015-06-07 11:41:30 9675 [Note] InnoDB: Highest supported file format is Barracuda. 2015-06-07 11:41:30 9675 [Note] InnoDB: Log scan progressed past the checkpoint lsn 3446441494 2015-06-07 11:41:30 9675 [Note] InnoDB: Database was not shutdown normally! 2015-06-07 11:41:30 9675 [Note] InnoDB: Starting crash recovery. 2015-06-07 11:41:30 9675 [Note] InnoDB: Reading tablespace information from the .ibd files... 2015-06-07 11:41:30 9675 [Note] InnoDB: Restoring possible half-written data pages 2015-06-07 11:41:30 9675 [Note] InnoDB: from the doublewrite buffer... InnoDB: Doing recovery: scanned up to log sequence number 3451684352 InnoDB: Doing recovery: scanned up to log sequence number 3456927232 InnoDB: Doing recovery: scanned up to log sequence number 3462170112 InnoDB: Doing recovery: scanned up to log sequence number 3467412992 InnoDB: Doing recovery: scanned up to log sequence number 3472655872 InnoDB: Doing recovery: scanned up to log sequence number 3477898752 InnoDB: Doing recovery: scanned up to log sequence number 3483141632 InnoDB: Doing recovery: scanned up to log sequence number 3488384512 InnoDB: Doing recovery: scanned up to log sequence number 3493627392 InnoDB: Doing recovery: scanned up to log sequence number 3498870272 InnoDB: Doing recovery: scanned up to log sequence number 3504113152 InnoDB: Doing recovery: scanned up to log sequence number 3505201579 InnoDB: Transaction 505147 was in the XA prepared state. InnoDB: 2 transaction(s) which must be rolled back or cleaned up InnoDB: in total 1 row operations to undo InnoDB: Trx id counter is 505600 2015-06-07 11:41:31 9675 [Note] InnoDB: Starting an apply batch of log records to the database... InnoDB: Progress in percent: 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 61317041, file name dg6-logbin.000009 2015-06-07 11:41:40 9675 [Note] InnoDB: 128 rollback segment(s) are active. 2015-06-07 11:41:40 9675 [Note] InnoDB: Waiting for purge to start InnoDB: Starting in background the rollback of uncommitted transactions 2015-06-07 11:41:40 7f58dd9c2700 InnoDB: Rolling back trx with id 505160, 1 rows to undo 2015-06-07 11:41:40 9675 [Note] InnoDB: Rollback of trx with id 505160 completed 2015-06-07 11:41:40 7f58dd9c2700 InnoDB: Rollback of non-prepared transactions completed 2015-06-07 11:41:40 9675 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.21-rel70.1 started; log sequence number 3505201579 2015-06-07 11:41:40 9675 [Note] Recovering after a crash using dg6-logbin 2015-06-07 11:41:40 9675 [Note] Starting crash recovery... 2015-06-07 11:41:40 7f599fd1c7e0 InnoDB: Starting recovery for XA transactions... 2015-06-07 11:41:40 7f599fd1c7e0 InnoDB: Transaction 505147 in prepared state after recovery 2015-06-07 11:41:40 7f599fd1c7e0 InnoDB: Transaction contains changes to 1 rows 2015-06-07 11:41:40 7f599fd1c7e0 InnoDB: 1 transactions in prepared state after recovery 2015-06-07 11:41:40 9675 [Note] Found 1 prepared transaction(s) in InnoDB 2015-06-07 11:41:40 9675 [Note] Crash recovery finished. /opt/app/mysql/bin/mysqld: Found a Gtid_log_event or Previous_gtids_log_event when @@GLOBAL.GTID_MODE = OFF. /opt/app/mysql/bin/mysqld: Found a Gtid_log_event or Previous_gtids_log_event when @@GLOBAL.GTID_MODE = OFF. 2015-06-07 11:41:40 9675 [Note] RSA private key file not found: /data/mydata//private_key.pem. Some authentication plugins will not work. 2015-06-07 11:41:40 9675 [Note] RSA public key file not found: /data/mydata//public_key.pem. Some authentication plugins will not work. 2015-06-07 11:41:40 9675 [Note] Server hostname (bind-address): '*'; port: 3306 2015-06-07 11:41:40 9675 [Note] IPv6 is available. 2015-06-07 11:41:40 9675 [Note] - '::' resolves to '::'; 2015-06-07 11:41:40 9675 [Note] Server socket created on IP: '::'. 2015-06-07 11:41:40 9675 [Warning] 'user' entry 'root@dg1' ignored in --skip-name-resolve mode. 2015-06-07 11:41:40 9675 [Warning] 'proxies_priv' entry '@ root@dg1' ignored in --skip-name-resolve mode. 2015-06-07 11:41:40 9675 [Note] Event Scheduler: Loaded 0 events 2015-06-07 11:41:40 9675 [Note] /opt/app/mysql/bin/mysqld: ready for connections. Version: '5.6.21-70.1-log' socket: '/tmp/mysql.sock' port: 3306 Percona Server (GPL), Release 70.1, Revision 698
不科学呀，还是十几秒，那么我们改成4G，让压测运行时间更长一点，900秒以后在kill
2.3 innodb_log_file_size = 4096M
150607 12:06:18 mysqld_safe Starting mysqld daemon with databases from /data/mydata 2015-06-07 12:06:19 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details). 2015-06-07 12:06:19 13255 [Note] Plugin 'FEDERATED' is disabled. 2015-06-07 12:06:19 7fd6f83a67e0 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator. 2015-06-07 12:06:19 13255 [Note] InnoDB: Using atomics to ref count buffer pool pages 2015-06-07 12:06:19 13255 [Note] InnoDB: The InnoDB memory heap is disabled 2015-06-07 12:06:19 13255 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2015-06-07 12:06:19 13255 [Note] InnoDB: Memory barrier is not used 2015-06-07 12:06:19 13255 [Note] InnoDB: Compressed tables use zlib 1.2.3 2015-06-07 12:06:19 13255 [Note] InnoDB: Using Linux native AIO 2015-06-07 12:06:19 13255 [Note] InnoDB: Using CPU crc32 instructions 2015-06-07 12:06:19 13255 [Note] InnoDB: Initializing buffer pool, size = 2.0G 2015-06-07 12:06:19 13255 [Note] InnoDB: Completed initialization of buffer pool 2015-06-07 12:06:19 13255 [Note] InnoDB: Highest supported file format is Barracuda. 2015-06-07 12:06:19 13255 [Note] InnoDB: Log scan progressed past the checkpoint lsn 3505377488 2015-06-07 12:06:19 13255 [Note] InnoDB: Database was not shutdown normally! 2015-06-07 12:06:19 13255 [Note] InnoDB: Starting crash recovery. 2015-06-07 12:06:19 13255 [Note] InnoDB: Reading tablespace information from the .ibd files... 2015-06-07 12:06:20 13255 [Note] InnoDB: Restoring possible half-written data pages 2015-06-07 12:06:20 13255 [Note] InnoDB: from the doublewrite buffer... InnoDB: Doing recovery: scanned up to log sequence number 3510620160 InnoDB: Doing recovery: scanned up to log sequence number 3515863040 InnoDB: Doing recovery: scanned up to log sequence number 3521105920 InnoDB: Doing recovery: scanned up to log sequence number 3526348800 InnoDB: Doing recovery: scanned up to log sequence number 3531591680 InnoDB: Doing recovery: scanned up to log sequence number 3536834560 InnoDB: Doing recovery: scanned up to log sequence number 3542077440 InnoDB: Doing recovery: scanned up to log sequence number 3547320320 InnoDB: Doing recovery: scanned up to log sequence number 3552563200 InnoDB: Doing recovery: scanned up to log sequence number 3557806080 InnoDB: Doing recovery: scanned up to log sequence number 3563048960 InnoDB: Doing recovery: scanned up to log sequence number 3568291840 InnoDB: Doing recovery: scanned up to log sequence number 3573534720 InnoDB: Doing recovery: scanned up to log sequence number 3578777600 InnoDB: Doing recovery: scanned up to log sequence number 3584020480 InnoDB: Doing recovery: scanned up to log sequence number 3589263360 InnoDB: Doing recovery: scanned up to log sequence number 3594506240 InnoDB: Doing recovery: scanned up to log sequence number 3599749120 InnoDB: Doing recovery: scanned up to log sequence number 3604992000 InnoDB: Doing recovery: scanned up to log sequence number 3610234880 InnoDB: Doing recovery: scanned up to log sequence number 3615477760 InnoDB: Doing recovery: scanned up to log sequence number 3620720640 InnoDB: Doing recovery: scanned up to log sequence number 3625963520 InnoDB: Doing recovery: scanned up to log sequence number 3631206400 InnoDB: Doing recovery: scanned up to log sequence number 3636449280 InnoDB: Doing recovery: scanned up to log sequence number 3641692160 InnoDB: Doing recovery: scanned up to log sequence number 3646935040 InnoDB: Doing recovery: scanned up to log sequence number 3652177920 InnoDB: Doing recovery: scanned up to log sequence number 3657420800 InnoDB: Doing recovery: scanned up to log sequence number 3662227637 InnoDB: Transaction 743374 was in the XA prepared state. InnoDB: Transaction 743374 was in the XA prepared state. InnoDB: 2 transaction(s) which must be rolled back or cleaned up InnoDB: in total 1 row operations to undo InnoDB: Trx id counter is 743936 2015-06-07 12:06:24 13255 [Note] InnoDB: Starting an apply batch of log records to the database... InnoDB: Progress in percent: 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 171705192, file name dg6-logbin.000011 2015-06-07 12:06:43 13255 [Note] InnoDB: 128 rollback segment(s) are active. 2015-06-07 12:06:43 13255 [Note] InnoDB: Waiting for purge to start InnoDB: Starting in background the rollback of uncommitted transactions 2015-06-07 12:06:43 7fd635de8700 InnoDB: Rolling back trx with id 743385, 1 rows to undo 2015-06-07 12:06:43 13255 [Note] InnoDB: Rollback of trx with id 743385 completed 2015-06-07 12:06:43 7fd635de8700 InnoDB: Rollback of non-prepared transactions completed 2015-06-07 12:06:43 13255 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.21-rel70.1 started; log sequence number 3662227637 2015-06-07 12:06:43 13255 [Note] Recovering after a crash using dg6-logbin 2015-06-07 12:06:45 13255 [Note] Starting crash recovery... 2015-06-07 12:06:45 7fd6f83a67e0 InnoDB: Starting recovery for XA transactions... 2015-06-07 12:06:45 7fd6f83a67e0 InnoDB: Transaction 743374 in prepared state after recovery 2015-06-07 12:06:45 7fd6f83a67e0 InnoDB: Transaction contains changes to 2 rows 2015-06-07 12:06:45 7fd6f83a67e0 InnoDB: 1 transactions in prepared state after recovery 2015-06-07 12:06:45 13255 [Note] Found 1 prepared transaction(s) in InnoDB 2015-06-07 12:06:45 13255 [Note] Crash recovery finished. /opt/app/mysql/bin/mysqld: Found a Gtid_log_event or Previous_gtids_log_event when @@GLOBAL.GTID_MODE = OFF. /opt/app/mysql/bin/mysqld: Found a Gtid_log_event or Previous_gtids_log_event when @@GLOBAL.GTID_MODE = OFF. 2015-06-07 12:06:45 13255 [Note] RSA private key file not found: /data/mydata//private_key.pem. Some authentication plugins will not work. 2015-06-07 12:06:45 13255 [Note] RSA public key file not found: /data/mydata//public_key.pem. Some authentication plugins will not work. 2015-06-07 12:06:45 13255 [Note] Server hostname (bind-address): '*'; port: 3306 2015-06-07 12:06:45 13255 [Note] IPv6 is available. 2015-06-07 12:06:45 13255 [Note] - '::' resolves to '::'; 2015-06-07 12:06:45 13255 [Note] Server socket created on IP: '::'. 2015-06-07 12:06:45 13255 [Warning] 'user' entry 'root@dg1' ignored in --skip-name-resolve mode. 2015-06-07 12:06:45 13255 [Warning] 'proxies_priv' entry '@ root@dg1' ignored in --skip-name-resolve mode. 2015-06-07 12:06:45 13255 [Note] Event Scheduler: Loaded 0 events 2015-06-07 12:06:45 13255 [Note] /opt/app/mysql/bin/mysqld: ready for connections. Version: '5.6.21-70.1-log' socket: '/tmp/mysql.sock' port: 3306 Percona Server (GPL), Release 70.1, Revision 698
也才二十几秒钟。
那么我们看看5.5版本是什么情况 因为5.5版本redolog大小不能超过4G，所以单个不能设置成2048M否则会报错
150607 17:15:46 InnoDB: Error: combined size of log files must be < 4 GB
150607 17:15:46 [ERROR] Plugin 'InnoDB' init function returned error.
2.4 innodb_log_file_size = 1024M
150607 17:08:34 mysqld_safe Starting mysqld daemon with databases from /data/mydata 150607 17:08:34 [Warning] 'THREAD_CONCURRENCY' is deprecated and will be removed in a future release. 150607 17:08:34 [Note] /opt/app/mysql/bin/mysqld (mysqld 5.5.43-log) starting as process 3709 ... 150607 17:08:34 [Note] Plugin 'FEDERATED' is disabled. 150607 17:08:34 InnoDB: The InnoDB memory heap is disabled 150607 17:08:34 InnoDB: Mutexes and rw_locks use GCC atomic builtins 150607 17:08:34 InnoDB: Compressed tables use zlib 1.2.3 150607 17:08:34 InnoDB: Using Linux native AIO 150607 17:08:34 InnoDB: Initializing buffer pool, size = 2.0G 150607 17:08:34 InnoDB: Completed initialization of buffer pool 150607 17:08:34 InnoDB: highest supported file format is Barracuda. InnoDB: Log scan progressed past the checkpoint lsn 2740017318 150607 17:08:34 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 2745260032 InnoDB: Doing recovery: scanned up to log sequence number 2750502912 InnoDB: Doing recovery: scanned up to log sequence number 2755745792 InnoDB: Doing recovery: scanned up to log sequence number 2760988672 InnoDB: Doing recovery: scanned up to log sequence number 2766231552 InnoDB: Doing recovery: scanned up to log sequence number 2771474432 InnoDB: Doing recovery: scanned up to log sequence number 2776717312 InnoDB: Doing recovery: scanned up to log sequence number 2781960192 InnoDB: Doing recovery: scanned up to log sequence number 2787203072 InnoDB: Doing recovery: scanned up to log sequence number 2792445952 InnoDB: Doing recovery: scanned up to log sequence number 2797688832 InnoDB: Doing recovery: scanned up to log sequence number 2802931712 InnoDB: Doing recovery: scanned up to log sequence number 2808174592 InnoDB: Doing recovery: scanned up to log sequence number 2813417472 InnoDB: Doing recovery: scanned up to log sequence number 2818660352 InnoDB: Doing recovery: scanned up to log sequence number 2823903232 InnoDB: Doing recovery: scanned up to log sequence number 2824243265 InnoDB: Transaction 203E1 was in the XA prepared state. InnoDB: 1 transaction(s) which must be rolled back or cleaned up InnoDB: in total 0 row operations to undo InnoDB: Trx id counter is 20500 150607 17:08:36 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 923730775, file name ./mysql-bin.000005 InnoDB: Starting in background the rollback of uncommitted transactions 150607 17:08:45 InnoDB: Rollback of non-prepared transactions completed 150607 17:08:45 InnoDB: Waiting for the background threads to start 150607 17:08:46 InnoDB: 5.5.43 started; log sequence number 2824243265 150607 17:08:46 [Note] Recovering after a crash using mysql-bin 150607 17:08:54 [Note] Starting crash recovery... 150607 17:08:54 InnoDB: Starting recovery for XA transactions... 150607 17:08:54 InnoDB: Transaction 203E1 in prepared state after recovery 150607 17:08:54 InnoDB: Transaction contains changes to 2 rows 150607 17:08:54 InnoDB: 1 transactions in prepared state after recovery 150607 17:08:54 [Note] Found 1 prepared transaction(s) in InnoDB 150607 17:08:54 [Note] Crash recovery finished. 150607 17:08:54 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306 150607 17:08:54 [Note] - '0.0.0.0' resolves to '0.0.0.0'; 150607 17:08:54 [Note] Server socket created on IP: '0.0.0.0'. 150607 17:08:55 [Warning] 'user' entry 'root@dg1' ignored in --skip-name-resolve mode. 150607 17:08:55 [Warning] 'user' entry '@dg1' ignored in --skip-name-resolve mode. 150607 17:08:55 [Warning] 'proxies_priv' entry '@ root@dg1' ignored in --skip-name-resolve mode. 150607 17:08:55 [Note] Event Scheduler: Loaded 0 events 150607 17:08:55 [Note] /opt/app/mysql/bin/mysqld: ready for connections. Version: '5.5.43-log' socket: '/tmp/mysql.sock' port: 3306 MySQL Community Server (GPL)
也不会很慢二十几秒钟
总结：
在5.5版本以上，修改了恢复算法，崩溃恢复快了很多，但是这里面涉及到很多因素，buffer_pool ,脏页比例，TPS等，需要多次测试，因条件限制，没办法进行大buffer_pool，高并发测试，实际物理机测试时，根据自身情况选着合理参数测试
参考资料：来自姜大神的书
在InnoDB存储引擎内部，有两种Checkpoint，分别为：
Sharp Checkpoint
Fuzzy Checkpoint
Sharp Checkpoint发生在数据库关闭时将所有的脏页都刷新回磁盘，这是默认的工作方式，即参数innodb_fast_shutdown=1。
但是若数据库在运行时也使用Sharp Checkpoint，那么数据库的可用性就会受到很大的影响。故在InnoDB存储引擎内部使用Fuzzy Checkpoint进行页的刷新，即只刷新一部分脏页，而不是刷新所有的脏页回磁盘。
这里笔者进行了概括，在InnoDB存储引擎中可能发生如下几种情况的Fuzzy Checkpoint：
Master Thread Checkpoint
FLUSH_LRU_LIST Checkpoint
Async/Sync Flush Checkpoint
Dirty Page too much Checkpoint
对于Master Thread（2.5节会详细介绍各个版本中Master Thread的实现）中发生的Checkpoint，差不多以每秒或每十秒的速度从缓冲池的脏页列表中刷新一定比例的页回磁盘。这个过程是异步的，即此时InnoDB存储引擎可以进行其他的操作，用户查询线程不会阻塞。
FLUSH_LRU_LIST Checkpoint是因为InnoDB存储引擎需要保证LRU列表中需要有差不多100个空闲页可供使用。在InnoDB1.1.x版本之前，需要检查LRU列表中是否有足够的可用空间操作发生在用户查询线程中，显然这会阻塞用户的查询操作。倘若没有100个可用空闲页，那么InnoDB存储引擎会将LRU列表尾端的页移除。如果这些页中有脏页，那么需要进行Checkpoint，而这些页是来自LRU列表的，因此称为FLUSH_LRU_LIST Checkpoint。
而从MySQL 5.6版本，也就是InnoDB1.2.x版本开始，这个检查被放在了一个单独的Page Cleaner线程中进行，并且用户可以通过参数innodb_lru_scan_depth控制LRU列表中可用页的数量，该值默认为1024，如：
mysql> SHOW VARIABLES LIKE 'innodb_lru_scan_depth'\G;
*************************** 1. row ***************************
Variable_name: innodb_lru_scan_depth
Value: 1024
1 row in set (0.00 sec)
Async/Sync Flush Checkpoint指的是重做日志文件不可用的情况，这时需要强制将一些页刷新回磁盘，而此时脏页是从脏页列表中选取的。若将已经写入到重做日志的LSN记为redo_lsn，将已经刷新回磁盘最新页的LSN记为checkpoint_lsn，则可定义：
checkpoint_age = redo_lsn - checkpoint_lsn
再定义以下的变量：
async_water_mark = 75% * total_redo_log_file_size
sync_water_mark = 90% * total_redo_log_file_size
若每个重做日志文件的大小为1GB，并且定义了两个重做日志文件，则重做日志文件的总大小为2GB。那么async_water_mark=1.5GB，sync_water_mark=1.8GB。则：
当checkpoint_age<async_water_mark时，不需要刷新任何脏页到磁盘；
当async_water_mark<checkpoint_age<sync_water_mark时触发Async Flush，从Flush列表中刷新足够的脏页回磁盘，使得刷新后满足checkpoint_age<async_water_mark；
checkpoint_age>sync_water_mark这种情况一般很少发生，除非设置的重做日志文件太小，并且在进行类似LOAD DATA的BULK INSERT操作。此时触发Sync Flush操作，从Flush列表中刷新足够的脏页回磁盘，使得刷新后满足checkpoint_age<async_water_mark。
可见，Async/Sync Flush Checkpoint是为了保证重做日志的循环使用的可用性。在InnoDB 1.2.x版本之前，Async Flush Checkpoint会阻塞发现问题的用户查询线程，而Sync Flush Checkpoint会阻塞所有的用户查询线程，并且等待脏页刷新完成。从InnoDB 1.2.x版本开始——也就是MySQL 5.6版本，这部分的刷新操作同样放入到了单独的Page Cleaner Thread中，故不会阻塞用户查询线程。
MySQL官方版本并不能查看刷新页是从Flush列表中还是从LRU列表中进行Checkpoint的，也不知道因为重做日志而产生的Async/Sync Flush的次数。但是InnoSQL版本提供了方法，可以通过命令SHOW ENGINE INNODB STATUS来观察，如：
mysql> SHOW ENGINE INNODB STATUS\G;
*************************** 1. row ***************************
Type: InnoDB
……
LRU len: 112902, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
Async Flush: 0, Sync Flush: 0, LRU List Flush: 0, Flush List Flush: 111736
……
1 row in set (0.01 sec)
根据上述的信息，还可以对InnoDB存储引擎做更为深入的调优，这部分将在第9章中讲述。
最后一种Checkpoint的情况是Dirty Page too much，即脏页的数量太多，导致InnoDB存储引擎强制进行Checkpoint。其目的总的来说还是为了保证缓冲池中有足够可用的页。其可由参数innodb_max_dirty_pages_pct控制：
mysql>SHOW VARIABLES LIKE 'innodb_max_dirty_pages_pct'\G;
*************************** 1. row ***************************
Variable_name: innodb_max_dirty_pages_pct
Value: 75
1 row in set (0.00 sec)
innodb_max_dirty_pages_pct值为75表示，当缓冲池中脏页的数量占据75%时，强制进行Checkpoint，刷新一部分的脏页到磁盘。在InnoDB 1.0.x版本之前，该参数默认值为90，之后的版本都为75。
