Description:
MySQL seems stalled during recovery, keeping at 43% for more then 20 mins to become 44%, then finished recovery within 5mins.(Only that gap from 43~44, no operation on the mysqld server box).
121010 16:11:32 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 l
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
I grabbed four pmp info, list below:
$ pt-pmp
2012年 10月 10日 星期三 16:35:18 CST
18 pthread_cond_wait,os_cond_wait,os_event_wait_low,os_aio_simulated_handle,fil_aio_wait,io_handler_thread,start_thread,clone
1 pwrite64,os_file_pwrite,os_file_write_func,os_aio_func,pfs_os_aio_func,fil_io,buf_dblwr_write_single_page,buf_flush_write_block_low,buf_flush_page,buf_flush_single_page_from_LRU,buf_LRU_get_free_block,buf_page_init_for_read,buf_read_page_low,buf_read_recv_pages,recv_read_in_area,recv_apply_hashed_log_recs,recv_recovery_from_checkpoint_finish,innobase_start_or_create_for_mysql,innobase_init,ha_initialize_handlerton,plugin_initialize,plugin_init,init_server_components,mysqld_main,main
$ pt-pmp
2012年 10月 10日 星期三 16:35:30 CST
18 pthread_cond_wait,os_cond_wait,os_event_wait_low,os_aio_simulated_handle,fil_aio_wait,io_handler_thread,start_thread,clone
1 os_aio_simulated_wake_handler_thread,os_aio_simulated_wake_handler_threads,buf_flush_sync_datafiles,buf_flush_single_page_from_LRU,buf_LRU_get_free_block,buf_page_init_for_read,buf_read_page_low,buf_read_recv_pages,recv_read_in_area,recv_apply_hashed_log_recs,recv_recovery_from_checkpoint_finish,innobase_start_or_create_for_mysql,innobase_init,ha_initialize_handlerton,plugin_initialize,plugin_init,init_server_components,mysqld_main,main
$ pt-pmp
2012年 10月 10日 星期三 16:35:39 CST
18 pthread_cond_wait,os_cond_wait,os_event_wait_low,os_aio_simulated_handle,fil_aio_wait,io_handler_thread,start_thread,clone
1 mutex_exit_func,pfs_mutex_exit_func,buf_flush_single_page_from_LRU,buf_LRU_get_free_block,buf_page_init_for_read,buf_read_page_low,buf_read_recv_pages,recv_read_in_area,recv_apply_hashed_log_recs,recv_recovery_from_checkpoint_finish,innobase_start_or_create_for_mysql,innobase_init,ha_initialize_handlerton,plugin_initialize,plugin_init,init_server_components,mysqld_main,main
$ pt-pmp
2012年 10月 10日 星期三 16:37:19 CST
18 pthread_cond_wait,os_cond_wait,os_event_wait_low,os_aio_simulated_handle,fil_aio_wait,io_handler_thread,start_thread,clone
1 mutex_exit_func,pfs_mutex_exit_func,buf_flush_single_page_from_LRU,buf_LRU_get_free_block,buf_page_init_for_read,buf_read_page_low,buf_read_recv_pages,recv_read_in_area,recv_apply_hashed_log_recs,recv_recovery_from_checkpoint_finish,innobase_start_or_create_for_mysql,innobase_init,ha_initialize_handlerton,plugin_initialize,plugin_init,init_server_components,mysqld_main,main
Obviously,too much time is cost on buf_flush_single_page_from_LRU,which should be careful checked.
How to repeat:
It's not easy to repeat. The case is testing with 1024 tables and each with 500,000 records, kill the running mysql with SIGKILL, and then restart mysqld.