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

Data race in os_file_pread at os/os0file.cc:3308 on os_n_file_reads

    XMLWordPrintable

    Details

      Description

      Simply starting the server generates a race in os_file_pread on os_n_file_reads.
      Issue may be sporadic as (oddly?) it does not uniformly represent in opt/dbg versions (ref below).

      10.5.9 1435f35bdabd078f0c4e744ab4bdfd8d4acca3ea (Optimized)

      ... startup ...
      /test/10.5_opt_san/storage/innobase/os/os0file.cc:3308 in os_file_pread
      SUMMARY: ThreadSanitizer: data race 
      

      10.5.9 1435f35bdabd078f0c4e744ab4bdfd8d4acca3ea (Optimized)

      WARNING: ThreadSanitizer: data race (pid=2702489)
        Read of size 8 at 0x5574f389bc38 by thread T5 (mutexes: write M17663):
          #0 os_file_pread /test/10.5_opt_san/storage/innobase/os/os0file.cc:3308 (mariadbd+0x140ea82)
          #1 os_file_read_page /test/10.5_opt_san/storage/innobase/os/os0file.cc:3345 (mariadbd+0x140ea82)
          #2 os_file_read_func(IORequest const&, int, void*, unsigned long, unsigned long) /test/10.5_opt_san/storage/innobase/os/os0file.cc:3730 (mariadbd+0x140ffbf)
          #3 os_aio(IORequest const&, void*, unsigned long, unsigned long) /test/10.5_opt_san/storage/innobase/os/os0file.cc:4117 (mariadbd+0x140ffbf)
          #4 fil_space_t::io(IORequest const&, unsigned long, unsigned long, void*, buf_page_t*) /test/10.5_opt_san/storage/innobase/fil/fil0fil.cc:3431 (mariadbd+0x1634a88)
          #5 buf_read_page_low /test/10.5_opt_san/storage/innobase/buf/buf0rea.cc:344 (mariadbd+0x15d1e9e)
          #6 buf_read_page(page_id_t, unsigned long) /test/10.5_opt_san/storage/innobase/buf/buf0rea.cc:489 (mariadbd+0x15d1e9e)
          #7 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)
          #8 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)
          #9 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)
          #10 btr_pcur_open_low /test/10.5_opt_san/storage/innobase/include/btr0pcur.ic:441 (mariadbd+0x159aac6)
          #11 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)
          #12 dict_load_table_on_id(unsigned long, dict_err_ignore_t) /test/10.5_opt_san/storage/innobase/dict/dict0load.cc:3141 (mariadbd+0x160b42a)
          #13 dict_table_open_on_id_low /test/10.5_opt_san/storage/innobase/dict/dict0dict.cc:222 (mariadbd+0x15f2e12)
          #14 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)
          #15 row_purge_parse_undo_rec /test/10.5_opt_san/storage/innobase/row/row0purge.cc:932 (mariadbd+0x14aea74)
          #16 row_purge /test/10.5_opt_san/storage/innobase/row/row0purge.cc:1105 (mariadbd+0x14aea74)
          #17 row_purge_step(que_thr_t*) /test/10.5_opt_san/storage/innobase/row/row0purge.cc:1157 (mariadbd+0x14aea74)
          #18 que_thr_step /test/10.5_opt_san/storage/innobase/que/que0que.cc:947 (mariadbd+0x1448047)
          #19 que_run_threads_low /test/10.5_opt_san/storage/innobase/que/que0que.cc:1009 (mariadbd+0x1448047)
          #20 que_run_threads(que_thr_t*) /test/10.5_opt_san/storage/innobase/que/que0que.cc:1049 (mariadbd+0x1448047)
          #21 trx_purge(unsigned long, bool) /test/10.5_opt_san/storage/innobase/trx/trx0purge.cc:1300 (mariadbd+0x1500120)
          #22 srv_do_purge /test/10.5_opt_san/storage/innobase/srv/srv0srv.cc:1995 (mariadbd+0x14e2120)
          #23 purge_coordinator_callback_low /test/10.5_opt_san/storage/innobase/srv/srv0srv.cc:2085 (mariadbd+0x14e2120)
          #24 purge_coordinator_callback /test/10.5_opt_san/storage/innobase/srv/srv0srv.cc:2114 (mariadbd+0x14e2120)
          #25 tpool::task_group::execute(tpool::task*) /test/10.5_opt_san/tpool/task_group.cc:55 (mariadbd+0x16f43dd)
          #26 tpool::task::execute() /test/10.5_opt_san/tpool/task.cc:47 (mariadbd+0x16f48b2)
          #27 tpool::thread_pool_generic::worker_main(tpool::worker_data*) /test/10.5_opt_san/tpool/tpool_generic.cc:546 (mariadbd+0x16f1b54)
          #28 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)
          #29 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)
          #30 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)
          #31 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)
          #32 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)
          #33 <null> <null> (libstdc++.so.6+0xd6d83)
       
        Previous write of size 8 at 0x5574f389bc38 by thread T7:
          #0 os_file_pread /test/10.5_opt_san/storage/innobase/os/os0file.cc:3308 (mariadbd+0x140ea99)
          #1 os_file_read_page /test/10.5_opt_san/storage/innobase/os/os0file.cc:3345 (mariadbd+0x140ea99)
          #2 os_file_read_func(IORequest const&, int, void*, unsigned long, unsigned long) /test/10.5_opt_san/storage/innobase/os/os0file.cc:3730 (mariadbd+0x140ffbf)
          #3 os_aio(IORequest const&, void*, unsigned long, unsigned long) /test/10.5_opt_san/storage/innobase/os/os0file.cc:4117 (mariadbd+0x140ffbf)
          #4 fil_space_t::io(IORequest const&, unsigned long, unsigned long, void*, buf_page_t*) /test/10.5_opt_san/storage/innobase/fil/fil0fil.cc:3431 (mariadbd+0x1634a88)
          #5 buf_read_page_low /test/10.5_opt_san/storage/innobase/buf/buf0rea.cc:344 (mariadbd+0x15d2183)
          #6 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+0x15d2183)
          #7 buf_load /test/10.5_opt_san/storage/innobase/buf/buf0dump.cc:677 (mariadbd+0x15c2622)
          #8 buf_dump_load_func /test/10.5_opt_san/storage/innobase/buf/buf0dump.cc:758 (mariadbd+0x15c31e1)
          #9 tpool::task::execute() /test/10.5_opt_san/tpool/task.cc:52 (mariadbd+0x16f48df)
          #10 tpool::thread_pool_generic::worker_main(tpool::worker_data*) /test/10.5_opt_san/tpool/tpool_generic.cc:546 (mariadbd+0x16f1b54)
          #11 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)
          #12 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)
          #13 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)
          #14 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)
          #15 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)
          #16 <null> <null> (libstdc++.so.6+0xd6d83)
       
        Location is global 'os_n_file_reads' of size 8 at 0x5574f389bc38 (mariadbd+0x000002b2ac38)
       
        Mutex M17663 (0x5574f2f7b200) 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=2702722, 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=2702743, 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/os/os0file.cc:3308 in os_file_pread
      

      {
        ut_ad(type.is_read());
        ++os_n_file_reads;                                                  <------------- 3308
       
        const bool monitor = MONITOR_IS_ON(MONITOR_OS_PENDING_READS);
        MONITOR_ATOMIC_INC_LOW(MONITOR_OS_PENDING_READS, monitor);
        ssize_t n_bytes = os_file_io(type, file, buf, n, offset, err);
        MONITOR_ATOMIC_DEC_LOW(MONITOR_OS_PENDING_READS, monitor);
       
        return(n_bytes);
      }
      

      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.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 (opt), 10.6.0 (dbg)

        Attachments

          Activity

            People

            Assignee:
            kevg Eugene Kosov
            Reporter:
            Roel Roel Van de Paar
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: