Bug #100330 mysql instance hang
Submitted: 27 Jul 2020 6:41 Modified: 29 Jul 2020 12:37
Reporter: w yj Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server Severity:S2 (Serious)
Version:5.7.25 OS:CentOS (2.6.32-504.el6.x86_64)
Assigned to: CPU Architecture:x86 (Xeon(R) CPU E5-2690 v3)

[27 Jul 2020 6:41] w yj 
Description:
1. executed normally: select 1 or select user();
2. cannot be executed: select * from information_schema.processlist; or show global status; or  Any business statement .

How to repeat:
not repeat
[27 Jul 2020 6:44] w yj 
pstack

Attachment: pstack.txt.zip (application/zip, text), 297.13 KiB.
[27 Jul 2020 6:44] w yj 
--------- Automatic recovery takes about 30 minutes
--------- error log
2020-07-24T12:17:59.232026+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 1883487ms. The settings might not be optimal. (flushed=16 and evicted=0, during the time.)
2020-07-24T12:17:59.232978+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 48042104203008 has waited at row0sel.cc line 5124 for 1883.00 seconds the semaphore:
S-lock on RW-latch at 0x2b9dae4b9ba0 created in file buf0buf.cc line 1460
a writer (thread id 48044825032448) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0ins.cc line 2510
Last time write locked in file /export/home/pb2/build/sb_0-32013917-1545390211.74/mysql-5.7.25/storage/innobase/include/mtr0mtr.ic line 153
2020-07-24T12:17:59.233027+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 48041499424512 has waited at buf0lru.cc line 1320 for 1882.00 seconds the semaphore:
Mutex at 0x2cdd788, Mutex BUF_POOL created buf0buf.cc:1731, lock var 0
2020-07-24T12:17:59.233052+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 48045038606080 has waited at buf0lru.cc line 1139 for 1883.00 seconds the semaphore:
Mutex at 0x2cdd2c8, Mutex BUF_POOL created buf0buf.cc:1731, lock var 0
2020-07-24T12:17:59.233064+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 48044825032448 has waited at buf0lru.cc line 1139 for 1883.00 seconds the semaphore:
Mutex at 0x2cdd2c8, Mutex BUF_POOL created buf0buf.cc:1731, lock var 0
2020-07-24T12:17:59.233073+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 48044201883392 has waited at buf0lru.cc line 1320 for 1883.00 seconds the semaphore:
Mutex at 0x2cdd2c8, Mutex BUF_POOL created buf0buf.cc:1731, lock var 0
2020-07-24T12:17:59.233082+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 48043906279168 has waited at btr0cur.cc line 976 for 1883.00 seconds the semaphore:
SX-lock on RW-latch at 0x2bb1540c9f10 created in file dict0dict.cc line 2737
a writer (thread id 48044825032448) has reserved it in mode  SX
number of readers 8, waiters flag 1, lock_word: ffffff8
Last time read locked in file btr0cur.cc line 1008
Last time write locked in file /export/home/pb2/build/sb_0-32013917-1545390211.74/mysql-5.7.25/storage/innobase/btr/btr0cur.cc line 976
[27 Jul 2020 6:46] w yj 
--- Here is a trace using pt-pmp.

      1 sigwait(libpthread.so.0),signal_hand,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 sigwaitinfo(libc.so.6),timer_notify_thread_func,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,sync_array_wait_event,TTASEventMutex::wait,PolicyMutex::enter,srv_export_innodb_status,show_innodb_vars,PFS_status_variable_cache::manifest,PFS_status_variable_cache::do_materialize_global,table_global_status::rnd_init,ha_perfschema::rnd_init,handler::ha_rnd_init,init_read_record,join_init_read_record,sub_select,JOIN::exec,TABLE_LIST::materialize_derived,join_materialize_derived,QEP_TAB::prepare_scan,sub_select,JOIN::exec,handle_query,execute_sqlcom_select,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,sync_array_wait_event,TTASEventMutex::wait,PolicyMutex::enter,srv_error_monitor_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,sync_array_wait_event,TTASEventMutex::wait,PolicyMutex::enter,innobase_show_status,ha_show_status,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,sync_array_wait_event,TTASEventMutex::wait,PolicyMutex::enter,buf_stats_get_pool_info,buf_print_io,srv_printf_innodb_monitor,innobase_show_status,ha_show_status,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,sync_array_wait_event,TTASEventMutex::wait,PolicyMutex::enter,buf_LRU_get_free_block,buf_block_alloc,btr_page_reorganize_low,btr_cur_optimistic_insert,row_ins_clust_index_entry_low,row_ins_clust_index_entry,row_ins_step,row_insert_for_mysql_using_ins_graph,ha_innobase::write_row,handler::ha_write_row,write_record,Sql_cmd_insert::mysql_insert,Sql_cmd_insert::execute,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,sync_array_wait_event,TTASEventMutex::wait,PolicyMutex::enter,buf_LRU_get_free_block,buf_block_alloc,btr_page_reorganize_low,btr_cur_insert_if_possible,btr_cur_optimistic_update,row_upd_clust_rec,row_upd_clust_step,row_upd,row_upd_step,row_update_for_mysql_using_upd_graph,row_update_for_mysql,ha_innobase::update_row,handler::ha_update_row,mysql_update,Sql_cmd_update::try_single_table_update,Sql_cmd_update::execute,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,sync_array_wait_event,TTASEventMutex::wait,PolicyMutex::enter,buf_LRU_buf_pool_running_out,row_ins_sorted_clust_index_entry,row_insert_for_mysql_using_cursor,ha_innobase::intrinsic_table_write_row,ha_innobase::write_row,handler::ha_write_row,schema_table_store_record,Fill_process_list::operator,Global_THD_manager::do_for_all_thd_copy,fill_schema_processlist,do_fill_table,get_schema_tables_result,JOIN::prepare_result,JOIN::exec,handle_query,execute_sqlcom_select,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,sync_array_wait_event,rw_lock_s_lock_spin,buf_page_get_gen,btr_cur_search_to_nth_level,row_sel_get_clust_rec_for_mysql,row_search_mvcc,ha_innobase::index_read,handler::index_read_idx_map,handler::ha_index_read_idx_map,st_table_ref*),st_position*),JOIN::extract_func_dependent_tables,JOIN::make_join_plan,JOIN::optimize,st_select_lex::optimize,handle_query,execute_sqlcom_select,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,sync_array_wait_event,rw_lock_s_lock_spin,buf_page_get_gen,btr_cur_search_to_nth_level,row_sel_get_clust_rec_for_mysql,row_search_mvcc,ha_innobase::index_read,handler::ha_index_read_map,join_read_always_key,sub_select,JOIN::exec,handle_query,execute_sqlcom_select,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,srv_purge_coordinator_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,buf_resize_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,buf_flush_page_cleaner_coordinator,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,buf_dump_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,buf_dblwr_flush_buffered_writes,buf_flush_do_batch,pc_flush_slot,buf_flush_page_cleaner_worker,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,Event_scheduler::cond_wait,Event_scheduler::stop,event_scheduler_update,sys_var::update,set_var::update,sql_set_variables,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,compress_gtid_table,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,srv_monitor_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,lock_wait_timeout_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,ib_wqueue_timedwait,fts_optimize_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,dict_stats_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 poll(libc.so.6),Mysqld_socket_listener::listen_for_connection_event,mysqld_main,__libc_start_main(libc.so.6),_start
      1 nanosleep(libpthread.so.0),os_thread_sleep,srv_master_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 nanosleep(libpthread.so.0),os_thread_sleep,srv_conc_enter_innodb,ha_innobase::index_read,handler::ha_index_read_map,handler::read_range_first,handler::multi_range_read_next,DsMrr_impl::dsmrr_next,QUICK_RANGE_SELECT::get_next,rr_quick,mysql_update,Sql_cmd_update::try_single_table_update,Sql_cmd_update::execute,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 nanosleep(libpthread.so.0),os_thread_sleep,srv_conc_enter_innodb,ha_innobase::index_read,ha_innobase::index_first,ha_innobase::rnd_next,handler::ha_rnd_next,rr_sequential,sub_select,JOIN::exec,handle_query,execute_sqlcom_select,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 __lll_lock_wait(libpthread.so.0),_L_lock_995(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),THD::release_resources,deinit_event_thread,Event_scheduler::run,event_scheduler_thread,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 __lll_lock_wait(libpthread.so.0),_L_lock_995(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),inline_mysql_mutex_lock,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 __lll_lock_wait(libpthread.so.0),_L_lock_854(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),os_event_reset,buf_dblwr_add_to_batch,buf_flush_page,buf_flush_page_and_try_neighbors,buf_flush_do_batch,pc_flush_slot,buf_flush_page_cleaner_worker,start_thread(libpthread.so.0),clone(libc.so.6)
[27 Jul 2020 12:33] MySQL Verification Team 
Hi Mr. yj,

Thank you for your bug report.

However, we can not verify your report as a bug.

Simply, we do not have sufficient information. We require a fully repeatable test case, so that we can repeat it and diagnose the exact cause of the problem.

With your example, it is quite evident that your server is not tuned properly, which is a very frequent cause of the problems that you describe. Another, connected cause could be inappropriate hardware for the task at hand.

Last, but not least, you are using a very old release of 5.7. Try repeating a problem with 5.7.31.

In any case, we can not proceed without a fully repeatable test case as described above.
[29 Jul 2020 1:56] w yj 
maybe this bug caused
https://github.com/torvalds/linux/commit/76835b0ebf8a7fe85beb03c75121419a7dec52f0

after kernel upgraded, it seem no problem for long time.
[29 Jul 2020 12:37] MySQL Verification Team 
Hi Mr. yj,

Thank you for your feedback.

We do not maintain Linux kernel, and we are aware that, as any other software, it has its own bugs.

Not our bug.