Bug #73341 cant't shutdown server with --innodb-force-recovery=6
Submitted: 21 Jul 2014 13:37 Modified: 22 Sep 2014 18:50
Reporter: zhai weixiang (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.7,5.6, 5.6.19, 5.6.21 OS:Any
Assigned to: CPU Architecture:Any

[21 Jul 2014 13:37] zhai weixiang
Description:
can't shutdown a mysql instance if setting innodb-force-recovery = 6

And  releated backtrace:

      8 pthread_cond_wait,wait(os0event.cc:216),os_event::wait_low(os0event.cc:216),os_aio_simulated_handle(os0file.cc:5449),fil_aio_wait(fil0fil.cc:5484),io_handler_thread(srv0start.cc:285),start_thread(libpthread.so.0),clone(libc.so.6)
      1 sigwaitinfo(libc.so.6),timer_notify_thread_func(posix_timers.c:78),pfs_spawn_thread(pfs.cc:2072),start_thread(libpthread.so.0),clone(libc.so.6)
      1 nanosleep(libpthread.so.0),os_thread_sleep(os0thread.cc:265),logs_empty_and_mark_files_at_shutdown(log0log.cc:2051),innobase_shutdown_for_mysql(srv0start.cc:2472),innobase_end(ha_innodb.cc:3299),ha_finalize_handlerton(handler.cc:614),plugin_deinitialize(sql_plugin.cc:934),reap_plugins(sql_plugin.cc:934),plugin_shutdown(sql_plugin.cc:1706),clean_up(mysqld.cc:1447),mysqld_main(mysqld.cc:4763),__libc_start_main(libc.so.6),_start

How to repeat:
start the server with  innodb-force-recovery  = 6 ,and shutdown the server using mysqladmin

Suggested fix:
still debug it.
[21 Jul 2014 14:09] zhai weixiang
the shutdown thread hangs in function logs_empty_and_mark_files_at_shutdown.

and quoted code:

2235         if (lsn != log_sys->last_checkpoint_lsn
2236             ) {
2237
2238                 log_mutex_exit();
2239
2240                 goto loop;
2241         }

here log_sys->lsn != log_sys->last_checkpoint_lsn. But since we set innodb-force-recovery=6, there isn't any background thread   to make a  log checkpoint.....
[21 Jul 2014 15:03] zhai weixiang
And if  innodb force recovery  is larger than 3,  then  srv_read_only_mode is set to 1. log_make_checkpoint_at is not triggered by the shutdown thread.

quoted code from logs_empty_and_mark_files_at_shutdown:
2223         if (!srv_read_only_mode) {
2224                 log_make_checkpoint_at(LSN_MAX, TRUE);
2225         }
2226
2227         log_mutex_enter();
2228
2229         lsn = log_sys->lsn;
2230
2231         if (lsn != log_sys->last_checkpoint_lsn
2232             ) {
2233
2234                 log_mutex_exit();
2235
2236                 goto loop;
2237         }
[22 Jul 2014 1:54] zhai weixiang
I also make a clean shutdown without setting innodb-force-recovery  ,and then restart the server with innodb-force-recovery=6, still hang on shutdown.. :(
[22 Jul 2014 5:57] zhai weixiang
a simple fix  with a test case. make a fast shutdown when innodb_force_recovery=6

Attachment: bug73341.diff (application/octet-stream, text), 3.22 KiB.

[22 Jul 2014 6:54] MySQL Verification Team
Hello Zhai,

Thank you for the report.
Verified as described with 5.6.19.

Thanks,
Umesh
[22 Jul 2014 7:00] MySQL Verification Team
// 5.6.19    
  1 sigwait,signal_hand,pfs_spawn_thread,start_thread,clone
      1 select,os_thread_sleep,logs_empty_and_mark_files_at_shutdown,innobase_shutdown_for_mysql,innobase_end,ha_finalize_handlerton,plugin_deinitialize,reap_plugins,plugin_shutdown,clean_up,unireg_end,kill_server,optimized,pfs_spawn_thread,start_thread,clone
      1 pthread_cond_wait@@GLIBC_2.3.2,inline_mysql_cond_wait,argv=0x2ba8b78),__libc_start_main,_start
      1 ??,os_aio_linux_collect,message1=0x7f829f20ce58,,fil_aio_wait,io_handler_thread,start_thread,clone
      1 ??,os_aio_linux_collect,message1=0x7f828cadde58,,fil_aio_wait,io_handler_thread,start_thread,clone
      1 ??,os_aio_linux_collect,message1=0x7f828c2dce58,,fil_aio_wait,io_handler_thread,start_thread,clone
      1 ??,os_aio_linux_collect,message1=0x7f828badbe58,,fil_aio_wait,io_handler_thread,start_thread,clone
      1
[22 Jul 2014 7:03] MySQL Verification Team
// 5.6.21

      1 sigwait,signal_hand,pfs_spawn_thread,start_thread,clone
      1 select,os_thread_sleep,logs_empty_and_mark_files_at_shutdown,innobase_shutdown_for_mysql,innobase_end,ha_finalize_handlerton,plugin_deinitialize,at,plugin_shutdown,clean_up,unireg_end,kill_server,kill_server_thread,pfs_spawn_thread,start_thread,clone
      1 pthread_cond_wait@@GLIBC_2.3.2,inline_mysql_cond_wait,argv=0x29cad28),__libc_start_main,_start
      1 ??,os_aio_linux_collect,message1=0x7fe77ddb6e58,,fil_aio_wait,io_handler_thread,start_thread,clone
      1 ??,os_aio_linux_collect,message1=0x7fe77d5b5e58,,fil_aio_wait,io_handler_thread,start_thread,clone
      1 ??,os_aio_linux_collect,message1=0x7fe77cdb4e58,,fil_aio_wait,io_handler_thread,start_thread,clone
      1 ??,os_aio_linux_collect,message1=0x7fe77c5b3e58,,fil_aio_wait,io_handler_thread,start_thread,clone
      1
[22 Sep 2014 18:50] Daniel Price
Fixed as of the upcoming 5.6.22, 5.7.6 release, and here's the changelog entry:

Attempting to shut down the server after starting the server with
"innodb_force_recovery=6" would result in a hang. 

Thank you for the bug report.
[10 Dec 2014 13:08] Laurynas Biveinis
$ bzr log -r 6169
------------------------------------------------------------
revno: 6169
committer: bin.x.su@oracle.com
branch nick: mysql-5.6
timestamp: Mon 2014-09-22 14:19:36 +0800
message:
  Bug#19265668 CANT'T SHUTDOWN SERVER WITH --INNODB-FORCE-RECOVERY=6
  
  When starting the server with innodb_force_recovery=6 the server would
  hang if we try to shut it down. The root cause is that server is in
  read-only mode with innodb_force_recovery=6 and the log_sys->lsn is
  12 bytes(LOG_BLOCK_HDR_SIZE) after log_sys->last_checkpoint_lsn and
  these 2 will never change. We have to identify this case.
  
  rb#6280, approved by Jimmy.