Percona Server hangs during oltp prepare with several buffer pool instances and small innodb_log_file_size

Bug #1651657 reported by Nickolay Ihalainen
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Status tracked in 5.7
5.5
Invalid
Undecided
Unassigned
5.6
Fix Released
High
Nickolay Ihalainen
5.7
Fix Released
High
Nickolay Ihalainen

Bug Description

Hi,

The bug looks similar to:
https://bugs.launchpad.net/percona-server/+bug/1521905

Several buffer pool instances allows to have LRU < 256 pages per buffer pool, but backoff algorithm is still used
innodb_empty_free_list_algorithm backoff

There is no issue for --innodb_empty_free_list_algorithm=legacy case.

I'm running sysbench against mysqld 5.6 started from mysql-test-run with --loose-skip-log-bin --query-cache-type=0 --innodb_log_file_size=128M --innodb-buffer-pool-size=268435456 --innodb_buffer_pool_instances=4 --innodb_flush_log_at_trx_commit=0:
sysbench --test /usr/share/sysbench/tests/db/parallel_prepare.lua --oltp-read-only --oltp-range-size 1000 --rand-init on --oltp-dist-type uniform --oltp-table-size 250000 --mysql-socket /mnt/nvram/nickolay.ihalainen/build/mysql5.6/mysql-test/var/tmp/mysqld.1.sock --mysql-user root --oltp-tables-count 32 --num-threads 32 run

It's interesting that the problem strikes even if buffer pull slightly bigger than 20MB, because 20MB should be in LRU list.

It works fine with big innodb_log_file_size (e.g. 4GB), but works really slow for small log files.

SHOW ENGINE INNODB STATUS\G hangs

there is an aggregated stacktrace:
    138 select,os_thread_sleep(os0thread.cc:298),buf_LRU_get_free_block(buf0lru.cc:1408),buf_page_create(buf0buf.cc:4025),fsp_page_create(fsp0fsp.cc:1303),fseg_alloc_free_page_low(fsp0fsp.cc:2583),fseg_alloc_free_page_general(fsp0fsp.cc:2652),btr_page_alloc_low(btr0btr.cc:1163),btr_page_alloc(btr0btr.cc:1163),btr_page_split_and_insert(btr0btr.cc:3111),btr_cur_pessimistic_insert(btr0cur.cc:1733),row_ins_clust_index_entry_low(row0ins.cc:2533),row_ins_clust_index_entry(row0ins.cc:2963),row_ins_index_entry(row0ins.cc:3040),row_ins_index_entry_step(row0ins.cc:3040),row_ins(row0ins.cc:3040),row_ins_step(row0ins.cc:3040),row_insert_for_mysql(row0mysql.cc:1364),ha_innobase::write_row(ha_innodb.cc:7568),handler::ha_write_row(handler.cc:7736),write_record(sql_insert.cc:1957),mysql_insert(sql_insert.cc:1085
),mysql_execute_command(sql_parse.cc:3906),mysql_parse(sql_parse.cc:6972),dispatch_command(sql_parse.cc:1441),do_command(sql_parse.cc:1053),do_handle_one_connection(sql_connect.cc:1541),handle_one_connection(sql_connect.cc:1444),pfs_spawn_thread(pfs.cc:1860),start_thre
ad,clone
     30 __io_getevents_0_4,os_aio_linux_collect(os0file.cc:5228),os_aio_linux_handle(os0file.cc:5228),fil_aio_wait(fil0fil.cc:5907),io_handler_thread(srv0start.cc:515),start_thread,clone
     11 pthread_cond_wait,os_cond_wait(os0sync.cc:196),os_event_wait_low(os0sync.cc:196),sync_array_wait_event(sync0arr.cc:433),rw_lock_x_lock_func(sync0rw.cc:886),rw_lock_x_lock_func(sync0rw.cc:918),pfs_rw_lock_x_lock_func(sync0rw.ic:918),mtr_x_lock_func(sync0rw.ic:91
8),fsp_reserve_free_extents(sync0rw.ic:918),trx_undo_seg_create(trx0undo.cc:470),trx_undo_create(trx0undo.cc:470),trx_undo_assign_undo(trx0undo.cc:470),trx_undo_report_row_operation(trx0rec.cc:1261),btr_cur_ins_lock_and_undo(btr0cur.cc:1279),btr_cur_optimistic_insert(b
tr0cur.cc:1279),row_ins_clust_index_entry_low(row0ins.cc:2514),row_ins_clust_index_entry(row0ins.cc:2942),row_ins_index_entry(row0ins.cc:3040),row_ins_index_entry_step(row0ins.cc:3040),row_ins(row0ins.cc:3040),row_ins_step(row0ins.cc:3040),row_insert_for_mysql(row0mysq
l.cc:1364),ha_innobase::write_row(ha_innodb.cc:7568),handler::ha_write_row(handler.cc:7736),write_record(sql_insert.cc:1957),mysql_insert(sql_insert.cc:1085),mysql_execute_command(sql_parse.cc:3906),mysql_parse(sql_parse.cc:6972),dispatch_command(sql_parse.cc:1441),do_
command(sql_parse.cc:1053),do_handle_one_connection(sql_connect.cc:1541),handle_one_connection(sql_connect.cc:1444),pfs_spawn_thread(pfs.cc:1860),start_thread,clone
      5 select,os_thread_sleep(os0thread.cc:298),srv_master_sleep(srv0srv.cc:2960),srv_master_thread(srv0srv.cc:2960),start_thread,clone
      5 select,os_thread_sleep(os0thread.cc:298),page_cleaner_sleep_if_needed(buf0flu.cc:2584),buf_flush_lru_manager_thread(buf0flu.cc:2584),start_thread,clone
      5 select,os_thread_sleep(os0thread.cc:298),buf_LRU_get_free_block(buf0lru.cc:1408),buf_page_create(buf0buf.cc:4025),fsp_page_create(fsp0fsp.cc:1303),fsp_alloc_free_page(fsp0fsp.cc:1440),fseg_alloc_free_page_low(fsp0fsp.cc:2498),fseg_alloc_free_page_general(fsp0fs
p.cc:2652),trx_undo_add_page(trx0undo.cc:929),trx_undo_report_row_operation(trx0rec.cc:1383),btr_cur_ins_lock_and_undo(btr0cur.cc:1279),btr_cur_optimistic_insert(btr0cur.cc:1279),row_ins_clust_index_entry_low(row0ins.cc:2514),row_ins_clust_index_entry(row0ins.cc:2942),
row_ins_index_entry(row0ins.cc:3040),row_ins_index_entry_step(row0ins.cc:3040),row_ins(row0ins.cc:3040),row_ins_step(row0ins.cc:3040),row_insert_for_mysql(row0mysql.cc:1364),ha_innobase::write_row(ha_innodb.cc:7568),handler::ha_write_row(handler.cc:7736),write_record(s
ql_insert.cc:1957),mysql_insert(sql_insert.cc:1085),mysql_execute_command(sql_parse.cc:3906),mysql_parse(sql_parse.cc:6972),dispatch_command(sql_parse.cc:1441),do_command(sql_parse.cc:1053),do_handle_one_connection(sql_connect.cc:1541),handle_one_connection(sql_connect
.cc:1444),pfs_spawn_thread(pfs.cc:1860),start_thread,clone
      5 pthread_cond_wait,os_cond_wait(os0sync.cc:196),os_event_wait_low(os0sync.cc:196),srv_purge_coordinator_suspend(srv0srv.cc:3320),srv_purge_coordinator_thread(srv0srv.cc:3320),start_thread,clone
      5 pthread_cond_wait,os_cond_wait(os0sync.cc:196),os_event_wait_low(os0sync.cc:196),buf_dump_thread(buf0dump.cc:613),start_thread,clone
      5 pthread_cond_timedwait,os_cond_wait_timed(os0sync.cc:159),os_event_wait_time_low(os0sync.cc:159),srv_monitor_thread(srv0srv.cc:1936),start_thread,clone
      5 pthread_cond_timedwait,os_cond_wait_timed(os0sync.cc:159),os_event_wait_time_low(os0sync.cc:159),srv_error_monitor_thread(srv0srv.cc:2199),start_thread,clone
      5 pthread_cond_timedwait,os_cond_wait_timed(os0sync.cc:159),os_event_wait_time_low(os0sync.cc:159),lock_wait_timeout_thread(lock0wait.cc:503),start_thread,clone
      5 pthread_cond_timedwait,os_cond_wait_timed(os0sync.cc:159),os_event_wait_time_low(os0sync.cc:159),ib_wqueue_timedwait(ut0wqueue.cc:154),fts_optimize_thread(fts0opt.cc:3064),start_thread,clone
      5 pthread_cond_timedwait,os_cond_wait_timed(os0sync.cc:159),os_event_wait_time_low(os0sync.cc:159),dict_stats_thread(dict0stats_bg.cc:349),start_thread,clone
      5 poll,poll(poll2.h:41),handle_connections_sockets(poll2.h:41),mysqld_main(mysqld.cc:6093),__libc_start_main,_start
      5 do_sigwait,__sigwait,signal_hand(mysqld.cc:3488),pfs_spawn_thread(pfs.cc:1860),start_thread,clone
      5 do_sigwaitinfo,__GI___sigwaitinfo,timer_notify_thread(posix_timers.c:78),start_thread,clone
      4 pthread_cond_wait,os_cond_wait(os0sync.cc:196),os_event_wait_low(os0sync.cc:196),sync_array_wait_event(sync0arr.cc:433),rw_lock_x_lock_func(sync0rw.cc:886),rw_lock_x_lock_func(sync0rw.cc:918),pfs_rw_lock_x_lock_func(sync0rw.ic:918),mtr_x_lock_func(sync0rw.ic:91
8),fsp_reserve_free_extents(sync0rw.ic:918),trx_undo_add_page(trx0undo.cc:921),trx_undo_report_row_operation(trx0rec.cc:1383),btr_cur_ins_lock_and_undo(btr0cur.cc:1279),btr_cur_optimistic_insert(btr0cur.cc:1279),row_ins_clust_index_entry_low(row0ins.cc:2514),row_ins_cl
ust_index_entry(row0ins.cc:2942),row_ins_index_entry(row0ins.cc:3040),row_ins_index_entry_step(row0ins.cc:3040),row_ins(row0ins.cc:3040),row_ins_step(row0ins.cc:3040),row_insert_for_mysql(row0mysql.cc:1364),ha_innobase::write_row(ha_innodb.cc:7568),handler::ha_write_ro
w(handler.cc:7736),write_record(sql_insert.cc:1957),mysql_insert(sql_insert.cc:1085),mysql_execute_command(sql_parse.cc:3906),mysql_parse(sql_parse.cc:6972),dispatch_command(sql_parse.cc:1441),do_command(sql_parse.cc:1053),do_handle_one_connection(sql_connect.cc:1541),
handle_one_connection(sql_connect.cc:1444),pfs_spawn_thread(pfs.cc:1860),start_thread,clone
      3 select,os_thread_sleep(os0thread.cc:298),page_cleaner_sleep_if_needed(buf0flu.cc:2584),buf_flush_page_cleaner_thread(buf0flu.cc:2584),start_thread,clone
      2 pthread_cond_wait,os_cond_wait(os0sync.cc:196),os_event_wait_low(os0sync.cc:196),sync_array_wait_event(sync0arr.cc:433),rw_lock_s_lock_spin(sync0rw.cc:550),rw_lock_s_lock_func(sync0rw.ic:426),pfs_rw_lock_s_lock_func(sync0rw.ic:426),buf_flush_page(sync0rw.ic:426
),buf_flush_try_neighbors(buf0flu.cc:1303),buf_flush_page_and_try_neighbors(buf0flu.cc:1394),buf_do_flush_list_batch(buf0flu.cc:1394),buf_flush_batch(buf0flu.cc:1800),buf_flush_list(buf0flu.cc:1800),page_cleaner_do_flush_batch(buf0flu.cc:2356),page_cleaner_flush_pages_
if_needed(buf0flu.cc:2356),buf_flush_page_cleaner_thread(buf0flu.cc:2356),start_thread,clone
      1 pthread_cond_wait,os_cond_wait(os0sync.cc:196),os_event_wait_low(os0sync.cc:196),sync_array_wait_event(sync0arr.cc:433),rw_lock_x_lock_func(sync0rw.cc:886),rw_lock_x_lock_func(sync0rw.cc:918),pfs_rw_lock_x_lock_func(sync0rw.ic:918),mtr_x_lock_func(sync0rw.ic:918),fsp_reserve_free_extents(sync0rw.ic:918),trx_undo_add_page(trx0undo.cc:921),trx_undo_report_row_operation(trx0rec.cc:1383),btr_cur_ins_lock_and_undo(btr0cur.cc:1279),btr_cur_pessimistic_insert(btr0cur.cc:1279),row_ins_clust_index_entry_low(row0ins.cc:2533),row_ins_clust_index_entry(row0ins.cc:2963),row_ins_index_entry(row0ins.cc:3040),row_ins_index_entry_step(row0ins.cc:3040),row_ins(row0ins.cc:3040),row_ins_step(row0ins.cc:3040),row_insert_for_mysql(row0mysql.cc:1364),ha_innobase::write_row(ha_innodb.cc:7568),handler::ha_write_row(handler.cc:7736),write_record(sql_insert.cc:1957),mysql_insert(sql_insert.cc:1085),mysql_execute_command(sql_parse.cc:3906),mysql_parse(sql_parse.cc:6972),dispatch_command(sql_parse.cc:1441),do_command(sql_parse.cc:1053),do_handle_one_connection(sql_connect.cc:1541)
,handle_one_connection(sql_connect.cc:1444),pfs_spawn_thread(pfs.cc:1860),start_thread,clone
      1 my_mb_wc_latin1,validate_string(sql_string.cc:1266),Item::check_well_formed_result(item.cc:5966),Item_string::Item_string(item.h:2887),MYSQLparse(sql_yacc.yy:13458),parse_sql(sql_parse.cc:9005),mysql_parse(sql_parse.cc:9005),dispatch_command(sql_parse.cc:1441),do_command(sql_parse.cc:1053),do_handle_one_connection(sql_connect.cc:1541),handle_one_connection(sql_connect.cc:1444),pfs_spawn_thread(pfs.cc:1860),start_thread,clone
nickolay.ihalainen@bm-support01:~$ 138 select,os_thread_sleep(os0thread.cc:298),buf_LRU_get_free_block(buf0lru.cc:1408),buf_page_create(buf0buf.cc:4025),fsp_page_create(fsp0fsp.cc:1303),fseg_alloc_free_page_low(fsp0fsp.cc:2583),fseg_alloc_free_page_general(fsp0fsp.
cc:2652),btr_page_alloc_low(btr0btr.cc:1163),btr_page_alloc(btr0btr.cc:1163),btr_page_split_and_insert(btr0btr.cc:3111),btr_cur_pessimistic_insert(btr0cur.cc:1733),row_ins_clust_index_entry_low(row0ins.cc:2533),row_ins_clust_index_entry(row0ins.cc:2963),row_ins_index_e
ntry(row0ins.cc:3040),row_ins_index_entry_step(row0ins.cc:3040),row_ins(row0ins.cc:3040),row_ins_step(row0ins.cc:3040),row_insert_for_mysql(row0mysql.cc:1364),ha_innobase::write_row(ha_innodb.cc:7568),handler::ha_write_row(handler.cc:7736),write_record(sql_insert.cc:19
57),mysql_insert(sql_insert.cc:1085),mysql_execute_command(sql_parse.cc:3906),mysql_parse(sql_parse.cc:6972),dispatch_command(sql_parse.cc:1441),do_command(sql_parse.cc:1053),do_handle_one_connection(sql_connect.cc:1541),handle_one_connection(sql_connect.cc:1444),pfs_s
pawn_thread(pfs.cc:1860),start_thread,clone

Tags: lru-flusher
tags: added: lru-flusher
Revision history for this message
Nickolay Ihalainen (ihanick) wrote :
Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1042

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.