Bug #67175 recovery is very very slow in buf_flush_single_page_from_LRU
Submitted: 10 Oct 2012 9:08 Modified: 14 Jan 2013 17:18
Reporter: liu hickey (OCA) Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.6.7 OS:Any
Assigned to: CPU Architecture:Any
Tags: recovery; slow;buf_flush_single_page_from_LRU

[10 Oct 2012 9:08] liu hickey
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.
[14 Jan 2013 17:18] MySQL Verification Team
Hi,

This is a duplicate of an internally filed bug. Pelase check when 5.6.10 is released, if things will be better.
Bug 14125092 - INNODB CRASH RECOVERY TOO SLOW