Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-28920

Rescheduling of innodb_stats_func() missing

    XMLWordPrintable

    Details

      Description

      --source include/have_innodb.inc
      --source include/have_sequence.inc
      create table t1(f1 int, f2 int, index(f2), index(f1))engine=innodb;
      insert into t1 select seq, seq from seq_1_to_1000;
      select last_update into @upd_time from mysql.innodb_table_stats where table_name = 't1';
      select  n_rows into @n_rows_1 from mysql.innodb_table_stats where table_name = 't1';
      insert into t1 select seq, seq from seq_2000_to_3000;
      --echo # sleep 30
      sleep 30;
      select last_update into @upd_time_1 from mysql.innodb_table_stats where table_name = 't1';
      select  n_rows into @n_rows_2 from mysql.innodb_table_stats where table_name = 't1';
       
      --echo # Both should be 1
      select @upd_time_1 > @upd_time;
      select @n_rows_2 > @n_rows_1;
       
      --echo # sleep 40
      sleep 10;
      select last_update into @upd_time_1 from mysql.innodb_table_stats where table_name = 't1';
      select  n_rows into @n_rows_2 from mysql.innodb_table_stats where table_name = 't1';
       
      --echo  # Both should be 1
      select @upd_time_1 > @upd_time;
      select @n_rows_2 > @n_rows_1;
       
      drop table t1;
      

      Expected result:

      create table t1(f1 int, f2 int, index(f2), index(f1))engine=innodb;
      insert into t1 select seq, seq from seq_1_to_1000;
      select last_update into @upd_time from mysql.innodb_table_stats where table_name = 't1';
      select  n_rows into @n_rows_1 from mysql.innodb_table_stats where table_name = 't1';
      insert into t1 select seq, seq from seq_2000_to_3000;
      # sleep 30
      select last_update into @upd_time_1 from mysql.innodb_table_stats where table_name = 't1';
      select  n_rows into @n_rows_2 from mysql.innodb_table_stats where table_name = 't1';
      select @upd_time_1 > @upd_time;
      @upd_time_1 > @upd_time
      1
      select @n_rows_2 > @n_rows_1;
      @n_rows_2 > @n_rows_1
      1
      # sleep 40
      select last_update into @upd_time_1 from mysql.innodb_table_stats where table_name = 't1';
      select  n_rows into @n_rows_2 from mysql.innodb_table_stats where table_name = 't1';
      select @upd_time_1 > @upd_time;
      @upd_time_1 > @upd_time
      1
      select @n_rows_2 > @n_rows_1;
      @n_rows_2 > @n_rows_1
      1
      drop table t1;
      

      But you may get the 0 for select @upd_time_1 > @upd_time && select @n_rows_2 > @n_rows_1

      Run the test case in repeat mode

      ./mtr innodb.f1{,,,,,,,,,,,} --repeat=10 --parallel=auto --mem 


      and you may get the result content mismatch because background thread stats didn't update
      the statistics of the table

      I can able to repeat with the help of rr. Background thread fails to reschedule
      in some case and dict_stats_func() wasn't called at all.
      The following stacktrace could give glimpse of the problem.

      (rr) t 5
      [Switching to thread 5 (Thread 25547.25616)]
      #0  0x00007fe6178433ad in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1
      (rr) where
      #0  0x00007fe6178433ad in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1
      #1  0x00007fe617844306 in _Unwind_Backtrace () from /lib/x86_64-linux-gnu/libgcc_s.so.1
      #2  0x00007fe617572fc8 in __GI___backtrace (array=<optimized out>, size=<optimized out>) at ../sysdeps/x86_64/backtrace.c:111
      #3  0x000055ae6f92dc3f in sf_malloc (size=2072, my_flags=0) at /home/thiru/mariarepo/10.6/10.6-test/mysys/safemalloc.c:147
      #4  0x000055ae6f91ad3d in my_malloc (key=0, size=2048, my_flags=0) at /home/thiru/mariarepo/10.6/10.6-test/mysys/my_malloc.c:90
      #5  0x000055ae6f8ed636 in init_dynamic_array2 (psi_key=0, array=0x7fe5bc00a410, element_size=16, init_buffer=0x0, init_alloc=128, alloc_increment=64, my_flags=0) at /home/thiru/mariarepo/10.6/10.6-test/mysys/array.c:71
      #6  0x000055ae6f8f3960 in my_hash_init2 (psi_key=0, hash=0x7fe5bc00a3e8, growth_size=64, charset=0x55ae707a54a0 <my_charset_bin>, size=128, key_offset=40, key_length=8, get_key=0x0, hash_function=0x0, free_element=0x0, flags=1) at /home/thiru/mariarepo/10.6/10.6-test/mysys/hash.c:98
      #7  0x000055ae6f92591a in safe_mutex_lazy_init_deadlock_detection (mp=0x7fe5bc008980) at /home/thiru/mariarepo/10.6/10.6-test/mysys/thr_mutex.c:172
      #8  0x000055ae6f925dcf in safe_mutex_lock (mp=0x7fe5bc008980, my_flags=0, file=0x55ae6fb1f4c8 "/home/thiru/mariarepo/10.6/10.6-test/sql/sql_class.cc", line=7862) at /home/thiru/mariarepo/10.6/10.6-test/mysys/thr_mutex.c:316
      #9  0x000055ae6f91f520 in psi_mutex_lock (that=0x7fe5bc008980, file=0x55ae6fb1f4c8 "/home/thiru/mariarepo/10.6/10.6-test/sql/sql_class.cc", line=7862) at /home/thiru/mariarepo/10.6/10.6-test/mysys/my_thr_init.c:487
      #10 0x000055ae6ec598a7 in inline_mysql_mutex_lock (that=0x7fe5bc008980, src_file=0x55ae6fb1f4c8 "/home/thiru/mariarepo/10.6/10.6-test/sql/sql_class.cc", src_line=7862) at /home/thiru/mariarepo/10.6/10.6-test/include/mysql/psi/mysql_thread.h:746
      #11 0x000055ae6ec703e4 in wait_for_commit::~wait_for_commit (this=0x7fe5bc008980, __in_chrg=<optimized out>) at /home/thiru/mariarepo/10.6/10.6-test/sql/sql_class.cc:7862
      #12 0x000055ae6ec5f8cf in THD::~THD (this=0x7fe5bc001f48, __in_chrg=<optimized out>) at /home/thiru/mariarepo/10.6/10.6-test/sql/sql_class.cc:1664
      #13 0x000055ae6ec5facc in THD::~THD (this=0x7fe5bc001f48, __in_chrg=<optimized out>) at /home/thiru/mariarepo/10.6/10.6-test/sql/sql_class.cc:1755
      #14 0x000055ae6ec69d93 in destroy_background_thd (thd=0x7fe5bc001f48) at /home/thiru/mariarepo/10.6/10.6-test/sql/sql_class.cc:5052
      #15 0x000055ae6f472fe6 in innobase_destroy_background_thd (thd=0x7fe5bc001f48) at /home/thiru/mariarepo/10.6/10.6-test/storage/innobase/handler/ha_innodb.cc:1840
      #16 0x000055ae6f7df28b in dict_stats_func () at /home/thiru/mariarepo/10.6/10.6-test/storage/innobase/dict/dict0stats_bg.cc:405
      #17 0x000055ae6f87eb72 in tpool::thread_pool_generic::timer_generic::run (this=0x55ae71dc07c0) at /home/thiru/mariarepo/10.6/10.6-test/tpool/tpool_generic.cc:352
      #18 0x000055ae6f87ec88 in tpool::thread_pool_generic::timer_generic::execute (arg=0x55ae71dc07c0) at /home/thiru/mariarepo/10.6/10.6-test/tpool/tpool_generic.cc:371
      #19 0x000055ae6f883bcd in tpool::task::execute (this=0x55ae71dc0800) at /home/thiru/mariarepo/10.6/10.6-test/tpool/task.cc:37
      #20 0x000055ae6f87d2b0 in tpool::thread_pool_generic::worker_main (this=0x55ae71c66930, thread_var=0x55ae71c75e50) at /home/thiru/mariarepo/10.6/10.6-test/tpool/tpool_generic.cc:588
      #21 0x000055ae6f880a47 in std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__f=@0x7fe5f8003018: (void (tpool::thread_pool_generic::*)(class tpool::thread_pool_generic * const, struct tpool::worker_data *)) 0x55ae6f87d218 <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>, __t=@0x7fe5f8003010: 0x55ae71c66930) at /usr/include/c++/8/bits/invoke.h:73
      #22 0x000055ae6f87fbe9 in std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__fn=@0x7fe5f8003018: (void (tpool::thread_pool_generic::*)(class tpool::thread_pool_generic * const, struct tpool::worker_data *)) 0x55ae6f87d218 <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>) at /usr/include/c++/8/bits/invoke.h:95
      #23 0x000055ae6f8835df in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul> (this=0x7fe5f8003008) at /usr/include/c++/8/thread:244
      #24 0x000055ae6f88357e in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator() (this=0x7fe5f8003008) at /usr/include/c++/8/thread:253
      #25 0x000055ae6f883562 in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run (this=0x7fe5f8003000) at /usr/include/c++/8/thread:196
      #26 0x00007fe617ebd4c0 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
      #27 0x00007fe6184016db in start_thread (arg=0x7fe5cd4fb700) at pthread_create.c:463
      #28 0x00007fe61756361f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      

      At the same time, InnoDB adds the table in recalc_pool and request reschedule now.

      #0  tpool::thread_pool_generic::timer_generic::set_time (this=0x55ae71dc07c0, initial_delay_ms=0, period_ms=0) at /home/thiru/mariarepo/10.6/10.6-test/tpool/tpool_generic.cc:409
      #1  0x000055ae6f7df381 in dict_stats_schedule (ms=0) at /home/thiru/mariarepo/10.6/10.6-test/storage/innobase/dict/dict0stats_bg.cc:430
      #2  0x000055ae6f7df3c6 in dict_stats_schedule_now () at /home/thiru/mariarepo/10.6/10.6-test/storage/innobase/dict/dict0stats_bg.cc:435
      #3  0x000055ae6f7de3d8 in dict_stats_recalc_pool_add (id=22) at /home/thiru/mariarepo/10.6/10.6-test/storage/innobase/dict/dict0stats_bg.cc:120
      #4  0x000055ae6f7de53c in dict_stats_update_if_needed (table=0x7fe5a41005d8, trx=@0x7fe611590b80: {<ilist_node<void>> = {next = 0x7fe611590080, prev = 0x55ae7078d300 <trx_sys+320>}, n_ref = {m_counter = {<std::__atomic_base<int>> = {_M_i = 0}, <No data fields>}}, id = 86, mutex = {lock = {<std::__atomic_base<unsigned int>> = {_M_i = 0}, <No data fields>}}, mutex_owner = {<std::__atomic_base<unsigned long>> = {_M_i = 0}, <No data fields>}, state = {m = {_M_i = TRX_STATE_ACTIVE}}, lock = {wait_lock = {m = {_M_b = {_M_p = 0x0}}}, wait_trx = 0x0, cond = pthread_cond_t = {Threads known to still execute a wait function = 0, Clock ID = CLOCK_REALTIME, Shared = No}, suspend_time = {m = {_M_i = {val = 0}}}, was_chosen_as_deadlock_victim = {m = {<std::__atomic_base<unsigned char>> = {_M_i = 0 '\000'}, <No data fields>}}, rec_cached = 0 '\000', table_cached = 1 '\001', wait_thr = 0x0, rec_pool = {{lock = {trx = 0x0, trx_locks = {prev = 0x0, next = 0x0}, index = 0x0, hash = 0x0, requested_time = 0, wait_time = 0, un_member = {tab_lock = {table = 0x0, locks = {prev = 0x0, next = 0x0}}, rec_lock = {page_id = {m_id = 0}, n_bits = 0}}, type_mode = 0}}, {lock = {trx = 0x0, trx_locks = {prev = 0x0, next = 0x0}, index = 0x0, hash = 0x0, requested_time = 0, wait_time = 0, un_member = {tab_lock = {table = 0x0, locks = {prev = 0x0, next = 0x0}}, rec_lock = {page_id = {m_id = 0}, n_bits = 0}}, type_mode = 0}}, {lock = {trx = 0x0, trx_locks = {prev = 0x0, next = 0x0}, index = 0x0, hash = 0x0, requested_time = 0, wait_time = 0, un_member = {tab_lock = {table = 0x0, locks = {prev = 0x0, next = 0x0}}, rec_lock = {page_id = {m_id = 0}, n_bits = 0}}, type_mode = 0}}, {lock = {trx = 0x0, trx_locks = {prev = 0x0, next = 0x0}, index = 0x0, hash = 0x0, requested_time = 0, wait_time = 0, un_member = {tab_lock = {table = 0x0, locks = {prev = 0x0, next = 0x0}}, rec_lock = {page_id = {m_id = 0}, n_bits = 0}}, type_mode = 0}}, {lock = {trx = 0x0, trx_locks = {prev = 0x0, next = 0x0}, index = 0x0, hash = 0x0, requested_time = 0, wait_time = 0, un_member = {tab_lock = {table = 0x0, locks = {prev = 0x0, next = 0x0}}, rec_lock = {page_id = {m_id = 0}, n_bits = 0}}, type_mode = 0}}, {lock = {trx = 0x0, trx_locks = {prev = 0x0, next = 0x0}, index = 0x0, hash = 0x0, requested_time = 0, wait_time = 0, un_member = {tab_lock = {table = 0x0, locks = {prev = 0x0, next = 0x0}}, rec_lock = {page_id = {m_id = 0}, n_bits = 0}}, type_mode = 0}}, {lock = {trx = 0x0, trx_locks = {prev = 0x0, next = 0x0}, index = 0x0, hash = 0x0, requested_time = 0, wait_time = 0, un_member = {tab_lock = {table = 0x0, locks = {prevG = 0x0, next = 0x0}}, rec_lock = {page_id = {m_id = 0}, n_bits = 0}}, type_mode = 0}}, {lock = {trx = 0x0, trx_locks = {prev = 0x0, next = 0x0}, index = 0x0, hash = 0x0, requested_time = 0, wait_time = 0, un_member = {tab_lock = {table = 0x0, locks = {prev = 0x0, next = 0x0}}, rec_lock = {page_id = {m_id = 0}, n_bits = 0}}, type_mode = 0}}}, table_pool = {{trx = 0x7fe611590b80, trx_locks = {prev = 0x0, next = 0x0}, index = 0x0, hash = 0x0, requested_time = 0, wait_time = 0, un_member = {tab_lock = {table = 0x7fe5a41005d8, locks = {prev = 0x0, next = 0x0}}, rec_lock = {page_id = {m_id = 140624276751832}, n_bits = 0}}, type_mode = 9}, {trx = 0x7fe611590b80, trx_locks = {prev = 0x0, next = 0x0}, index = 0x0, hash = 0x0, requested_time = 0, wait_time = 0, un_member = {tab_lock = {table = 0x55ae71d8d5a8, locks = {prev = 0x0, next = 0x0}}, rec_lock = {page_id = {m_id = 94207722706344}, n_bits = 0}}, type_mode = 11}, {trx = 0x7fe611590b80, trx_locks = {prev = 0x0, next = 0x0}, index = 0x0, hash = 0x0, requested_time = 0, wait_time = 0, un_member = {tab_lock = {table = 0x55ae71d8e0c8, locks = {prev = 0x0, next = 0x0}}, rec_lock = {page_id = {m_id = 94207722709192}, n_bits = 0}}, type_mode = 11}, {trx = 0x7fe611590b80, trx_locks = {prev = 0x0, next = 0x0}, index = 0x0, hash = 0x0, requested_time = 0, wait_time = 0, un_member = {tab_lock = {table = 0x55ae71d8f608, locks = {prev = 0x0, next = 0x0}}, rec_lock = {page_id = {m_id = 94207722714632}, n_bits = 0}}, type_mode = 11}, {trx = 0x7fe611590b80, trx_locks = {prev = 0x0, next = 0x0}, index = 0x0, hash = 0x0, requested_time = 0, wait_time = 0, un_member = {tab_lock = {table = 0x55ae71da7df8, locks = {prev = 0x0, next = 0x0}}, rec_lock = {page_id = {m_id = 94207722814968}, n_bits = 0}}, type_mode = 11}, {trx = 0x7fe611590b80, trx_locks = {prev = 0x0, next = 0x0}, index = 0x0, hash = 0x0, requested_time = 0, wait_time = 0, un_member = {tab_lock = {table = 0x55ae71daa9a8, locks = {prev = 0x0, next = 0x0}}, rec_lock = {page_id = {m_id = 94207722826152}, n_bits = 0}}, type_mode = 11}, {trx = 0x7fe611590b80, trx_locks = {prev = 0x0, next = 0x0}, index = 0x0, hash = 0x0, requested_time = 0, wait_time = 0, un_member = {tab_lock = {table = 0x55ae71dab5b8, locks = {prev = 0x0, next = 0x0}}, rec_lock = {page_id = {m_id = 94207722829240}, n_bits = 0}}, type_mode = 11}, {trx = 0x0, trx_locks = {prev = 0x0, next = 0x0}, index = 0x0, hash = 0x0, requested_time = 0, wait_time = 0, un_member = {tab_lock = {table = 0x0, locks = {prev = 0x0, next = 0x0}}, rec_lock = {page_id = {m_id = 0}, n_bits = 0}}, type_mode = 0}}, lock_heap = 0x55ae71c8c8f8, trx_locks = {count = 1, start = 0x7fe611591080, end = 0x7fe611591080, node = &ib_lock_t::trx_locks, init = 51966}, table_locks = std::vector of length 1, capacity 8 = {0x7fe611591080}, evicted_tables = {count = 0, start = 0x0, end = 0x0, node = &dict_table_t::table_LRU, init = 51966}, n_rec_locks = 0}, wsrep = 0 '\000', read_view = {<ReadViewBase> = {m_low_limit_id = 79, m_up_limit_id = 79, m_ids = std::vector of length 0, capacity 32, m_low_limit_no = 79}, m_open = {_M_base = {_M_i = false}}, m_mutex = {lock = {<std::__atomic_base<unsigned int>> = {_M_i = 0}, <No data fields>}}, m_creator_trx_id = 0}, is_recovered = false, op_info = 0x55ae6fed39fa "inserting", isolation_level = 2, check_foreigns = true, bulk_insert = false, is_registered = true, active_commit_ordered = false, check_unique_secondary = true, flush_log_later = false, must_flush_log_later = false, duplicates = 0, dict_operation = false, was_dict_operation = false, dict_operation_lock_mode = false, start_time = 1655797378, start_time_micro = 1655797378740268, commit_lsn = 1209943, mysql_thd = 0x7fe5a4000d78, mysql_log_file_name = 0x0, mysql_log_offset = 0, n_mysql_tables_in_use = 1, mysql_n_tables_locked = 1, error_state = DB_SUCCESS, error_info = 0x0, error_key_num = 18446744073709551615, graph = 0x0, trx_savepoints = {count = 0, start = 0x0, end = 0x0, node = &trx_named_savept_t::trx_savepoints, init = 51966}, undo_no = 31, last_sql_stat_start = {least_undo_no = 0}, rsegs = {m_redo = {rseg = 0x55ae70794fc0 <trx_sys+32256>, undo = 0x7fe5a4ba3878}, m_noredo = {rseg = 0x0, undo = 0x0}}, roll_limit = 0, in_rollback = false, pages_undone = 0, n_autoinc_rows = 0, autoinc_locks = 0x7fe5a420fcc8, read_only = false, auto_commit = false, will_lock = true, apply_online_log = false, fts_trx = 0x0, fts_next_doc_id = 0, flush_tables = 0, start_line = 1284, start_file = 0x55ae6fed2ee0 "/home/thiru/mariarepo/10.6/10.6-test/storage/innobase/row/row0mysql.cc", xid = {formatID = -1, gtrid_length = 0, bqual_length = 0, data = '\000' <repeats 127 times>}, mod_tables = std::map with 1 element = {[0x7fe5a41005d8] = {first = 0, first_versioned = 18446744073709551615}}, detailed_error = 0x55ae71c8c7d8 "", rw_trx_hash_element = 0x55ae71ba82a8, rw_trx_hash_pins = 0x55ae71db8538, magic_n = 91118598}) at /home/thiru/mariarepo/10.6/10.6-test/storage/innobase/dict/dict0stats_bg.cc:187
      #5  0x000055ae6f63f767 in row_insert_for_mysql (mysql_rec=0x7fe5a4b7ab78 "\371\037", prebuilt=0x7fe5a4baa838, ins_mode=ROW_INS_NORMAL) at /home/thiru/mariarepo/10.6/10.6-test/storage/innobase/row/row0mysql.cc:1414
      #6  0x000055ae6f4812ca in ha_innobase::write_row (this=0x7fe5a4b7c6a0, record=0x7fe5a4b7ab78 "\371\037") at /home/thiru/mariarepo/10.6/10.6-test/storage/innobase/handler/ha_innodb.cc:7910
      #7  0x000055ae6f084c17 in handler::ha_write_row (this=0x7fe5a4b7c6a0, buf=0x7fe5a4b7ab78 "\371\037") at /home/thiru/mariarepo/10.6/10.6-test/sql/handler.cc:7549
      #8  0x000055ae6ec92058 in write_record (thd=0x7fe5a4000d78, table=0x7fe5a4ba7d18, info=0x7fe5a40174f0, sink=0x0) at /home/thiru/mariarepo/10.6/10.6-test/sql/sql_insert.cc:2151
      #9  0x000055ae6ec97bb1 in select_insert::send_data (this=0x7fe5a40174a0, values=@0x7fe5a4016010: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x7fe5a4016308, last = 0x7fe5a4016438, elements = 2}, <No data fields>}) at /home/thiru/mariarepo/10.6/10.6-test/sql/sql_insert.cc:4115
      #10 0x000055ae6ed834a7 in select_result_sink::send_data_with_check (this=0x7fe5a40174a0, items=@0x7fe5a4016010: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x7fe5a4016308, last = 0x7fe5a4016438, elements = 2}, <No data fields>}, u=0x7fe5a40050e0, sent=30) at /home/thiru/mariarepo/10.6/10.6-test/sql/sql_class.h:5680
      

      may be signal to schedule the background thread was lost ?

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              wlad Vladislav Vaintroub
              Reporter:
              thiru Thirunarayanan Balathandayuthapani
              Votes:
              1 Vote for this issue
              Watchers:
              5 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:

                  Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.