[MDEV-24328] Data race in buf_page_get_low at buf/buf0buf.cc:2946 and in buf_page_read_complete at buf/buf0buf.cc:4240 Created: 2020-12-02  Updated: 2021-09-06  Resolved: 2021-09-06

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.3, 10.4, 10.5, 10.6
Fix Version/s: 10.6.0

Type: Bug Priority: Major
Reporter: Roel Van de Paar Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: affects-tests, not-10.1, not-10.2, tsan

Issue Links:
Relates
relates to MDEV-21212 buf_page_get_gen -> buf_pool->stat.n_... Closed

 Description   

Simply starting the server (both optimized and debug) generates these data races, once at startup and once at shutdown:

10.5.9 1435f35bdabd078f0c4e744ab4bdfd8d4acca3ea (Optimized)

... startup ...
SUMMARY: ThreadSanitizer: data race /test/10.5_opt_san/storage/innobase/buf/buf0buf.cc:2946 in buf_page_get_low(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned int, mtr_t*, dberr_t*, bool)
SUMMARY: ThreadSanitizer: data race /test/10.5_opt_san/storage/innobase/buf/buf0buf.cc:4240 in buf_page_read_complete(buf_page_t*, fil_node_t const&)
... mysqladmin shutdown ...
SUMMARY: ThreadSanitizer: data race /test/10.5_opt_san/storage/innobase/buf/buf0buf.cc:2946 in buf_page_get_low(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned int, mtr_t*, dberr_t*, bool)
SUMMARY: ThreadSanitizer: data race /test/10.5_opt_san/storage/innobase/buf/buf0buf.cc:4240 in buf_page_read_complete(buf_page_t*, fil_node_t const&)

Bug confirmed present in:
MariaDB: 10.3.28 (dbg), 10.3.28 (opt), 10.4.18 (dbg), 10.4.18 (opt), 10.5.9 (dbg), 10.5.9 (opt), 10.6.0 (dbg), 10.6.0 (opt)

Bug confirmed not present in:
MariaDB: 10.1.49 (dbg), 10.1.49 (opt), 10.2.37 (dbg), 10.2.37 (opt)

10.5.9 1435f35bdabd078f0c4e744ab4bdfd8d4acca3ea (Optimized)

WARNING: ThreadSanitizer: data race (pid=2447609)
  Read of size 8 at 0x556e643a9068 by thread T5:
    #0 buf_page_get_low(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned int, mtr_t*, dberr_t*, bool) /test/10.5_opt_san/storage/innobase/buf/buf0buf.cc:2946 (mariadbd+0x15b2dc7)
    #1 buf_page_get_gen(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned int, mtr_t*, dberr_t*, bool) /test/10.5_opt_san/storage/innobase/buf/buf0buf.cc:3476 (mariadbd+0x15b4bf7)
    #2 trx_undo_get_first_rec(fil_space_t const&, unsigned int, unsigned short, unsigned long, buf_block_t*&, mtr_t*) /test/10.5_opt_san/storage/innobase/trx/trx0undo.cc:283 (mariadbd+0x15446a0)
    #3 trx_purge_read_undo_rec /test/10.5_opt_san/storage/innobase/trx/trx0purge.cc:926 (mariadbd+0x14f7ab2)
    #4 trx_purge_choose_next_log /test/10.5_opt_san/storage/innobase/trx/trx0purge.cc:965 (mariadbd+0x14faf7d)
    #5 trx_purge_fetch_next_rec /test/10.5_opt_san/storage/innobase/trx/trx0purge.cc:1067 (mariadbd+0x15002dc)
    #6 trx_purge_attach_undo_recs /test/10.5_opt_san/storage/innobase/trx/trx0purge.cc:1167 (mariadbd+0x15002dc)
    #7 trx_purge(unsigned long, bool) /test/10.5_opt_san/storage/innobase/trx/trx0purge.cc:1288 (mariadbd+0x15002dc)
    #8 srv_do_purge /test/10.5_opt_san/storage/innobase/srv/srv0srv.cc:1995 (mariadbd+0x14e2120)
    #9 purge_coordinator_callback_low /test/10.5_opt_san/storage/innobase/srv/srv0srv.cc:2085 (mariadbd+0x14e2120)
    #10 purge_coordinator_callback /test/10.5_opt_san/storage/innobase/srv/srv0srv.cc:2114 (mariadbd+0x14e2120)
    #11 tpool::task_group::execute(tpool::task*) /test/10.5_opt_san/tpool/task_group.cc:55 (mariadbd+0x16f43dd)
    #12 tpool::task::execute() /test/10.5_opt_san/tpool/task.cc:47 (mariadbd+0x16f48b2)
    #13 tpool::thread_pool_generic::worker_main(tpool::worker_data*) /test/10.5_opt_san/tpool/tpool_generic.cc:546 (mariadbd+0x16f1b54)
    #14 void std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(std::__invoke_memfun_deref, void (tpool::thread_pool_generic::*&&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&) /usr/include/c++/9/bits/invoke.h:73 (mariadbd+0x16f2a47)
    #15 std::__invoke_result<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>::type std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(void (tpool::thread_pool_generic::*&&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&) /usr/include/c++/9/bits/invoke.h:95 (mariadbd+0x16f2a47)
    #16 void 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>(std::_Index_tuple<0ul, 1ul, 2ul>) /usr/include/c++/9/thread:244 (mariadbd+0x16f2a47)
    #17 std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator()() /usr/include/c++/9/thread:251 (mariadbd+0x16f2a47)
    #18 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() /usr/include/c++/9/thread:195 (mariadbd+0x16f2a47)
    #19 <null> <null> (libstdc++.so.6+0xd6d83)
 
  Previous write of size 8 at 0x556e643a9068 by main thread:
    #0 buf_page_get_low(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned int, mtr_t*, dberr_t*, bool) /test/10.5_opt_san/storage/innobase/buf/buf0buf.cc:2946 (mariadbd+0x15b2dde)
    #1 buf_page_get_gen(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned int, mtr_t*, dberr_t*, bool) /test/10.5_opt_san/storage/innobase/buf/buf0buf.cc:3476 (mariadbd+0x15b4bf7)
    #2 btr_cur_open_at_index_side_func(bool, dict_index_t*, unsigned long, btr_cur_t*, unsigned long, char const*, unsigned int, mtr_t*) /test/10.5_opt_san/storage/innobase/btr/btr0cur.cc:2633 (mariadbd+0x15804fd)
    #3 btr_pcur_open_at_index_side /test/10.5_opt_san/storage/innobase/include/btr0pcur.ic:545 (mariadbd+0x13c2b33)
    #4 ibuf_update_max_tablespace_id() /test/10.5_opt_san/storage/innobase/ibuf/ibuf0ibuf.cc:2978 (mariadbd+0x13c2b33)
    #5 srv_start(bool) /test/10.5_opt_san/storage/innobase/srv/srv0start.cc:1910 (mariadbd+0x6751df)
    #6 innodb_init /test/10.5_opt_san/storage/innobase/handler/ha_innodb.cc:3922 (mariadbd+0x1360400)
    #7 ha_initialize_handlerton(st_plugin_int*) /test/10.5_opt_san/sql/handler.cc:645 (mariadbd+0xcf9547)
    #8 plugin_initialize /test/10.5_opt_san/sql/sql_plugin.cc:1459 (mariadbd+0x8d3f74)
    #9 plugin_init(int*, char**, int) /test/10.5_opt_san/sql/sql_plugin.cc:1751 (mariadbd+0x8d5cc3)
    #10 init_server_components /test/10.5_opt_san/sql/mysqld.cc:4913 (mariadbd+0x72043d)
    #11 mysqld_main(int, char**) /test/10.5_opt_san/sql/mysqld.cc:5496 (mariadbd+0x725bf4)
    #12 main /test/10.5_opt_san/sql/main.cc:25 (mariadbd+0x6b8455)
 
  Location is global 'buf_pool' of size 4928 at 0x556e643a8e80 (mariadbd+0x000002209068)
 
  Thread T5 (tid=2447791, running) created by main thread at:
    #0 pthread_create <null> (libtsan.so.0+0x5ea99)
    #1 std::thread::_M_start_thread(std::unique_ptr<std::thread::_State, std::default_delete<std::thread::_State> >, void (*)()) <null> (libstdc++.so.6+0xd7048)
    #2 tpool::thread_pool_generic::maybe_wake_or_create_thread() /test/10.5_opt_san/tpool/tpool_generic.cc:802 (mariadbd+0x16f2787)
    #3 tpool::thread_pool_generic::submit_task(tpool::task*) /test/10.5_opt_san/tpool/tpool_generic.cc:821 (mariadbd+0x16f2787)
    #4 buf_flush_lists(unsigned long, unsigned long) /test/10.5_opt_san/storage/innobase/buf/buf0flu.cc:1533 (mariadbd+0x15ca505)
    #5 buf_flush_sync() /test/10.5_opt_san/storage/innobase/buf/buf0flu.cc:2289 (mariadbd+0x15cbfe8)
    #6 recv_sys_t::apply(bool) /test/10.5_opt_san/storage/innobase/log/log0recv.cc:2731 (mariadbd+0x13f4379)
    #7 srv_start(bool) /test/10.5_opt_san/storage/innobase/srv/srv0start.cc:1490 (mariadbd+0x673e74)
    #8 innodb_init /test/10.5_opt_san/storage/innobase/handler/ha_innodb.cc:3922 (mariadbd+0x1360400)
    #9 ha_initialize_handlerton(st_plugin_int*) /test/10.5_opt_san/sql/handler.cc:645 (mariadbd+0xcf9547)
    #10 plugin_initialize /test/10.5_opt_san/sql/sql_plugin.cc:1459 (mariadbd+0x8d3f74)
    #11 plugin_init(int*, char**, int) /test/10.5_opt_san/sql/sql_plugin.cc:1751 (mariadbd+0x8d5cc3)
    #12 init_server_components /test/10.5_opt_san/sql/mysqld.cc:4913 (mariadbd+0x72043d)
    #13 mysqld_main(int, char**) /test/10.5_opt_san/sql/mysqld.cc:5496 (mariadbd+0x725bf4)
    #14 main /test/10.5_opt_san/sql/main.cc:25 (mariadbd+0x6b8455)
 
SUMMARY: ThreadSanitizer: data race /test/10.5_opt_san/storage/innobase/buf/buf0buf.cc:2946 in buf_page_get_low(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned int, mtr_t*, dberr_t*, bool)

  case BUF_GET_IF_IN_POOL_OR_WATCH:
    fil_space_t* s = fil_space_get(page_id.space());
    ut_ad(s);
    ut_ad(s->zip_size() == zip_size);
  }
#endif /* UNIV_DEBUG */
 
  ut_ad(!mtr || !ibuf_inside(mtr)
        || ibuf_page_low(page_id, zip_size, FALSE, file, line, NULL));
 
  buf_pool.stat.n_page_gets++;        <----------------------- Here
loop:
  buf_block_t* fix_block;
  block = guess;
 
  page_hash_latch* hash_lock = buf_pool.page_hash.lock<false>(fold);

10.5.9 1435f35bdabd078f0c4e744ab4bdfd8d4acca3ea (Optimized)

WARNING: ThreadSanitizer: data race (pid=2447609)
  Read of size 8 at 0x556e643a9070 by thread T5 (mutexes: write M17663):
    #0 buf_page_read_complete(buf_page_t*, fil_node_t const&) /test/10.5_opt_san/storage/innobase/buf/buf0buf.cc:4240 (mariadbd+0x15b1b9d)
    #1 buf_read_page_low /test/10.5_opt_san/storage/innobase/buf/buf0rea.cc:360 (mariadbd+0x15d1ebe)
    #2 buf_read_page(page_id_t, unsigned long) /test/10.5_opt_san/storage/innobase/buf/buf0rea.cc:489 (mariadbd+0x15d1ebe)
    #3 buf_page_get_low(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned int, mtr_t*, dberr_t*, bool) /test/10.5_opt_san/storage/innobase/buf/buf0buf.cc:3019 (mariadbd+0x15b30b8)
    #4 buf_page_get_gen(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned int, mtr_t*, dberr_t*, bool) /test/10.5_opt_san/storage/innobase/buf/buf0buf.cc:3476 (mariadbd+0x15b4bf7)
    #5 btr_cur_search_to_nth_level_func(dict_index_t*, unsigned long, dtuple_t const*, page_cur_mode_t, unsigned long, btr_cur_t*, rw_lock_t*, char const*, unsigned int, mtr_t*, unsigned long) /test/10.5_opt_san/storage/innobase/btr/btr0cur.cc:1609 (mariadbd+0x158cf82)
    #6 btr_pcur_open_low /test/10.5_opt_san/storage/innobase/include/btr0pcur.ic:441 (mariadbd+0x159aac6)
    #7 btr_pcur_open_on_user_rec_func(dict_index_t*, dtuple_t const*, page_cur_mode_t, unsigned long, btr_pcur_t*, char const*, unsigned int, mtr_t*) /test/10.5_opt_san/storage/innobase/btr/btr0pcur.cc:648 (mariadbd+0x159ab9a)
    #8 dict_load_table_on_id(unsigned long, dict_err_ignore_t) /test/10.5_opt_san/storage/innobase/dict/dict0load.cc:3141 (mariadbd+0x160b42a)
    #9 dict_table_open_on_id_low /test/10.5_opt_san/storage/innobase/dict/dict0dict.cc:222 (mariadbd+0x15f2e12)
    #10 dict_table_open_on_id(unsigned long, bool, dict_table_op_t, THD*, MDL_ticket**) /test/10.5_opt_san/storage/innobase/dict/dict0dict.cc:948 (mariadbd+0x15f2e12)
    #11 row_purge_parse_undo_rec /test/10.5_opt_san/storage/innobase/row/row0purge.cc:932 (mariadbd+0x14aea74)
    #12 row_purge /test/10.5_opt_san/storage/innobase/row/row0purge.cc:1105 (mariadbd+0x14aea74)
    #13 row_purge_step(que_thr_t*) /test/10.5_opt_san/storage/innobase/row/row0purge.cc:1157 (mariadbd+0x14aea74)
    #14 que_thr_step /test/10.5_opt_san/storage/innobase/que/que0que.cc:947 (mariadbd+0x1448047)
    #15 que_run_threads_low /test/10.5_opt_san/storage/innobase/que/que0que.cc:1009 (mariadbd+0x1448047)
    #16 que_run_threads(que_thr_t*) /test/10.5_opt_san/storage/innobase/que/que0que.cc:1049 (mariadbd+0x1448047)
    #17 trx_purge(unsigned long, bool) /test/10.5_opt_san/storage/innobase/trx/trx0purge.cc:1300 (mariadbd+0x1500120)
    #18 srv_do_purge /test/10.5_opt_san/storage/innobase/srv/srv0srv.cc:1995 (mariadbd+0x14e2120)
    #19 purge_coordinator_callback_low /test/10.5_opt_san/storage/innobase/srv/srv0srv.cc:2085 (mariadbd+0x14e2120)
    #20 purge_coordinator_callback /test/10.5_opt_san/storage/innobase/srv/srv0srv.cc:2114 (mariadbd+0x14e2120)
    #21 tpool::task_group::execute(tpool::task*) /test/10.5_opt_san/tpool/task_group.cc:55 (mariadbd+0x16f43dd)
    #22 tpool::task::execute() /test/10.5_opt_san/tpool/task.cc:47 (mariadbd+0x16f48b2)
    #23 tpool::thread_pool_generic::worker_main(tpool::worker_data*) /test/10.5_opt_san/tpool/tpool_generic.cc:546 (mariadbd+0x16f1b54)
    #24 void std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(std::__invoke_memfun_deref, void (tpool::thread_pool_generic::*&&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&) /usr/include/c++/9/bits/invoke.h:73 (mariadbd+0x16f2a47)
    #25 std::__invoke_result<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>::type std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(void (tpool::thread_pool_generic::*&&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&) /usr/include/c++/9/bits/invoke.h:95 (mariadbd+0x16f2a47)
    #26 void 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>(std::_Index_tuple<0ul, 1ul, 2ul>) /usr/include/c++/9/thread:244 (mariadbd+0x16f2a47)
    #27 std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator()() /usr/include/c++/9/thread:251 (mariadbd+0x16f2a47)
    #28 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() /usr/include/c++/9/thread:195 (mariadbd+0x16f2a47)
    #29 <null> <null> (libstdc++.so.6+0xd6d83)
 
  Previous write of size 8 at 0x556e643a9070 by thread T7:
    #0 buf_page_read_complete(buf_page_t*, fil_node_t const&) /test/10.5_opt_san/storage/innobase/buf/buf0buf.cc:4240 (mariadbd+0x15b1bb4)
    #1 buf_read_page_low /test/10.5_opt_san/storage/innobase/buf/buf0rea.cc:360 (mariadbd+0x15d22cd)
    #2 buf_read_page_background(fil_space_t*, page_id_t, unsigned long, bool) /test/10.5_opt_san/storage/innobase/buf/buf0rea.cc:510 (mariadbd+0x15d22cd)
    #3 buf_load /test/10.5_opt_san/storage/innobase/buf/buf0dump.cc:677 (mariadbd+0x15c2622)
    #4 buf_dump_load_func /test/10.5_opt_san/storage/innobase/buf/buf0dump.cc:758 (mariadbd+0x15c31e1)
    #5 tpool::task::execute() /test/10.5_opt_san/tpool/task.cc:52 (mariadbd+0x16f48df)
    #6 tpool::thread_pool_generic::worker_main(tpool::worker_data*) /test/10.5_opt_san/tpool/tpool_generic.cc:546 (mariadbd+0x16f1b54)
    #7 void std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(std::__invoke_memfun_deref, void (tpool::thread_pool_generic::*&&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&) /usr/include/c++/9/bits/invoke.h:73 (mariadbd+0x16f2a47)
    #8 std::__invoke_result<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>::type std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(void (tpool::thread_pool_generic::*&&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&) /usr/include/c++/9/bits/invoke.h:95 (mariadbd+0x16f2a47)
    #9 void 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>(std::_Index_tuple<0ul, 1ul, 2ul>) /usr/include/c++/9/thread:244 (mariadbd+0x16f2a47)
    #10 std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator()() /usr/include/c++/9/thread:251 (mariadbd+0x16f2a47)
    #11 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() /usr/include/c++/9/thread:195 (mariadbd+0x16f2a47)
    #12 <null> <null> (libstdc++.so.6+0xd6d83)
 
  Location is global 'buf_pool' of size 4928 at 0x556e643a8e80 (mariadbd+0x000002209070)
 
  Mutex M17663 (0x556e643aa200) created at:
    #0 pthread_mutex_init <null> (libtsan.so.0+0x4a636)
    #1 OSMutex::init() /test/10.5_opt_san/storage/innobase/include/sync0types.h:343 (mariadbd+0x15f2495)
    #2 OSTrackMutex<GenericPolicy>::init(latch_id_t, char const*, unsigned int) /test/10.5_opt_san/storage/innobase/include/ib0mutex.h:61 (mariadbd+0x15f2495)
    #3 PolicyMutex<OSTrackMutex<GenericPolicy> >::init(latch_id_t, char const*, unsigned int) /test/10.5_opt_san/storage/innobase/include/ib0mutex.h:657 (mariadbd+0x15f2495)
    #4 void mutex_init<PolicyMutex<OSTrackMutex<GenericPolicy> > >(PolicyMutex<OSTrackMutex<GenericPolicy> >*, latch_id_t, char const*, unsigned int) /test/10.5_opt_san/storage/innobase/include/ut0mutex.h:164 (mariadbd+0x15f2495)
    #5 dict_sys_t::create() /test/10.5_opt_san/storage/innobase/dict/dict0dict.cc:1032 (mariadbd+0x15f2495)
    #6 dict_boot() /test/10.5_opt_san/storage/innobase/dict/dict0boot.cc:254 (mariadbd+0x15d56ba)
    #7 srv_start(bool) /test/10.5_opt_san/storage/innobase/srv/srv0start.cc:1461 (mariadbd+0x673980)
    #8 innodb_init /test/10.5_opt_san/storage/innobase/handler/ha_innodb.cc:3922 (mariadbd+0x1360400)
    #9 ha_initialize_handlerton(st_plugin_int*) /test/10.5_opt_san/sql/handler.cc:645 (mariadbd+0xcf9547)
    #10 plugin_initialize /test/10.5_opt_san/sql/sql_plugin.cc:1459 (mariadbd+0x8d3f74)
    #11 plugin_init(int*, char**, int) /test/10.5_opt_san/sql/sql_plugin.cc:1751 (mariadbd+0x8d5cc3)
    #12 init_server_components /test/10.5_opt_san/sql/mysqld.cc:4913 (mariadbd+0x72043d)
    #13 mysqld_main(int, char**) /test/10.5_opt_san/sql/mysqld.cc:5496 (mariadbd+0x725bf4)
    #14 main /test/10.5_opt_san/sql/main.cc:25 (mariadbd+0x6b8455)
 
  Thread T5 (tid=2447791, running) created by main thread at:
    #0 pthread_create <null> (libtsan.so.0+0x5ea99)
    #1 std::thread::_M_start_thread(std::unique_ptr<std::thread::_State, std::default_delete<std::thread::_State> >, void (*)()) <null> (libstdc++.so.6+0xd7048)
    #2 tpool::thread_pool_generic::maybe_wake_or_create_thread() /test/10.5_opt_san/tpool/tpool_generic.cc:802 (mariadbd+0x16f2787)
    #3 tpool::thread_pool_generic::submit_task(tpool::task*) /test/10.5_opt_san/tpool/tpool_generic.cc:821 (mariadbd+0x16f2787)
    #4 buf_flush_lists(unsigned long, unsigned long) /test/10.5_opt_san/storage/innobase/buf/buf0flu.cc:1533 (mariadbd+0x15ca505)
    #5 buf_flush_sync() /test/10.5_opt_san/storage/innobase/buf/buf0flu.cc:2289 (mariadbd+0x15cbfe8)
    #6 recv_sys_t::apply(bool) /test/10.5_opt_san/storage/innobase/log/log0recv.cc:2731 (mariadbd+0x13f4379)
    #7 srv_start(bool) /test/10.5_opt_san/storage/innobase/srv/srv0start.cc:1490 (mariadbd+0x673e74)
    #8 innodb_init /test/10.5_opt_san/storage/innobase/handler/ha_innodb.cc:3922 (mariadbd+0x1360400)
    #9 ha_initialize_handlerton(st_plugin_int*) /test/10.5_opt_san/sql/handler.cc:645 (mariadbd+0xcf9547)
    #10 plugin_initialize /test/10.5_opt_san/sql/sql_plugin.cc:1459 (mariadbd+0x8d3f74)
    #11 plugin_init(int*, char**, int) /test/10.5_opt_san/sql/sql_plugin.cc:1751 (mariadbd+0x8d5cc3)
    #12 init_server_components /test/10.5_opt_san/sql/mysqld.cc:4913 (mariadbd+0x72043d)
    #13 mysqld_main(int, char**) /test/10.5_opt_san/sql/mysqld.cc:5496 (mariadbd+0x725bf4)
    #14 main /test/10.5_opt_san/sql/main.cc:25 (mariadbd+0x6b8455)
 
  Thread T7 (tid=2447806, running) created by thread T1 at:
    #0 pthread_create <null> (libtsan.so.0+0x5ea99)
    #1 std::thread::_M_start_thread(std::unique_ptr<std::thread::_State, std::default_delete<std::thread::_State> >, void (*)()) <null> (libstdc++.so.6+0xd7048)
    #2 tpool::thread_pool_generic::maybe_wake_or_create_thread() /test/10.5_opt_san/tpool/tpool_generic.cc:802 (mariadbd+0x16f2787)
    #3 tpool::thread_pool_generic::submit_task(tpool::task*) /test/10.5_opt_san/tpool/tpool_generic.cc:821 (mariadbd+0x16f2787)
    #4 tpool::thread_pool_generic::timer_generic::submit_task(void*) /test/10.5_opt_san/tpool/tpool_generic.cc:335 (mariadbd+0x16f28c9)
    #5 process_timers /test/10.5_opt_san/mysys/thr_timer.c:271 (mariadbd+0x17b289b)
    #6 timer_handler /test/10.5_opt_san/mysys/thr_timer.c:315 (mariadbd+0x17b289b)
    #7 <null> <null> (libtsan.so.0+0x2d1af)
 
SUMMARY: ThreadSanitizer: data race /test/10.5_opt_san/storage/innobase/buf/buf0buf.cc:4240 in buf_page_read_complete(buf_page_t*, fil_node_t const&)

  /* Because this thread which does the unlocking might not be the same that
  did the locking, we use a pass value != 0 in unlock, which simply
  removes the newest lock debug record, without checking the thread id. */
  if (bpage->state() == BUF_BLOCK_FILE_PAGE)
    rw_lock_x_unlock_gen(&((buf_block_t*) bpage)->lock, BUF_IO_READ);
  bpage->io_unfix();
 
  ut_d(auto n=) buf_pool.n_pend_reads--;
  ut_ad(n > 0);
  buf_pool.stat.n_pages_read++;        <----------------------- Here
 
  return DB_SUCCESS;
}

Setup:

Compiled with GCC >=7.5.0 (I use GCC 9.3.0) and:
    -DWITH_TSAN=ON -DWSREP_LIB_WITH_TSAN=ON -DMUTEXTYPE=sys
Set before execution:
    export TSAN_OPTIONS=suppress_equal_stacks=1:suppress_equal_addresses=1:history_size=7:verbosity=1:exitcode=0

Bug confirmed present in:
MariaDB: 10.3.28 (dbg), 10.3.28 (opt), 10.4.18 (dbg), 10.4.18 (opt), 10.5.9 (dbg), 10.5.9 (opt), 10.6.0 (opt)

Bug confirmed not present in:
MariaDB: 10.1.49 (dbg), 10.1.49 (opt), 10.2.37 (dbg), 10.2.37 (opt), 10.6.0 (dbg)



 Comments   
Comment by Roel Van de Paar [ 2020-12-02 ]

The error appears after InnoDB start:

2020-12-02 12:25:27 0 [Note] InnoDB: 10.5.9 started; log sequence number 45094; transaction id 20

And before buffer pool load:

2020-12-02 12:25:27 0 [Note] InnoDB: Loading buffer pool(s) from /test/TSAN_MD011220-mariadb-10.5.9-linux-x86_64-opt/data/ib_buffer_pool

Comment by Marko Mäkelä [ 2021-09-06 ]

I think that this race should have been fixed by MDEV-21212. I was not able to repeat it in 10.6.

Comment by Roel Van de Paar [ 2021-09-06 ]

Confirmed no such issue is visible anymore in 10.6.5 @ 4c1ed54bfcb1ac08eb9b3221fba563ff55ac8f86 nor in 10.5.13 @a1b0f2358620335e9495242270cf47a1366c9a6a.

Generated at Thu Feb 08 09:29:09 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.