Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.5.4
Description
ASAN failure during shutdown on
|
origin/bb-10.5-MDEV-15053-3 be3c9a23fd014ed80d48e2984dec78db921a7a00 2020-06-02T20:37:37+03:00
|
|
2020-06-03 11:25:43 0 [Note] bin/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown
|
2020-06-03 11:25:43 3 [Warning] Aborted connection 3 to db: 'mysql' user: 'root' host: 'localhost' (This connection closed normally)
|
2020-06-03 11:25:44 0 [Note] Event Scheduler: Purging the queue. 0 events
|
=================================================================
|
==19477==ERROR: AddressSanitizer: heap-use-after-free on address 0x6120000044c8 at pc 0x55c74d8b6675 bp 0x7479707197f0 sp 0x7479707197e0
|
READ of size 1 at 0x6120000044c8 thread T105
|
#0 0x55c74d8b6674 in tpool::thread_pool_generic::timer_generic::set_time(int, int) /home/mleich/bb-10.5-MDEV-15053-3/tpool/tpool_generic.cc:348
|
#1 0x55c74d812496 in fts_optimize_callback storage/innobase/fts/fts0opt.cc:2872
|
#2 0x55c74d8c131f in tpool::task_group::execute(tpool::task*) tpool/task_group.cc:55
|
#3 0x55c74d8c1c6a in tpool::task::execute() tpool/task.cc:47
|
#4 0x55c74d8b218d in tpool::thread_pool_generic::worker_main(tpool::worker_data*) tpool/tpool_generic.cc:518
|
#5 0x55c74d8baae5 in 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++/7/bits/invoke.h:73
|
#6 0x55c74d8b88ec in 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++/7/bits/invoke.h:95
|
#7 0x55c74d8c0c56 in decltype (__invoke((_S_declval<0ul>)(), (_S_declval<1ul>)(), (_S_declval<2ul>)())) 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>) (bin/mariadbd+0x35b4c56)
|
#8 0x55c74d8c0ba4 in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator()() (bin/mariadbd+0x35b4ba4)
|
#9 0x55c74d8c0b05 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() (bin/mariadbd+0x35b4b05)
|
#10 0x3204548e46de (/usr/lib/x86_64-linux-gnu/libstdc++.so.6+0xbd6de)
|
#11 0x31295b0e06da in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76da)
|
#12 0x320454eed88e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x12188e)
|
...
|
SUMMARY: AddressSanitizer: heap-use-after-free tpool/tpool_generic.cc:348 in tpool::thread_pool_generic::timer_generic::set_time(int, int)
|
|
RQG
|
-------
|
git clone https://github.com/mleich1/rqg --branch experimental RQG_mleich
|
origin/experimental 5c63068c24fa6d687422f4d26490b067ff6535e4 2020-05-28T13:50:30+02:00
|
|
perl rqg.pl \
|
--mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \
|
--gendata=conf/mariadb/table_stress.zz \
|
--gendata_sql=conf/mariadb/table_stress.sql \
|
--engine=Innodb \
|
--reporters=Deadlock1,ErrorLog,Backtrace \
|
--mysqld=--connect_timeout=60 \
|
--mysqld=--net_read_timeout=30 \
|
--mysqld=--net_write_timeout=60 \
|
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
|
--mysqld=--loose-idle_transaction_timeout=0 \
|
--mysqld=--loose-idle_write_transaction_timeout=0 \
|
--mysqld=--interactive_timeout=28800 \
|
--mysqld=--lock_wait_timeout=86400 \
|
--mysqld=--innodb-lock-wait-timeout=50 \
|
--mysqld=--loose-table_lock_wait_timeout=50 \
|
--mysqld=--wait_timeout=28800 \
|
--mysqld=--slave_net_timeout=60 \
|
--mysqld=--loose-max-statement-time=30 \
|
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
|
--mysqld=--log-output=none \
|
--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
|
--duration=300 \
|
--seed=random \
|
--grammar=conf/mariadb/table_stress_innodb.yy \
|
--threads=33 \
|
--mysqld=--innodb_stats_persistent=ON \
|
--mysqld=--innodb_adaptive_hash_index=ON \
|
--mysqld=--innodb_page_size=64K \
|
--mysqld=--innodb-buffer-pool-size=24M \
|
--duration=300 \
|
--no_mask \
|
--workdir=<local settings> \
|
--vardir=<local settings> \
|
--mtr-build-thread=<local settings> \
|
--basedir1=<local settings> \
|
--basedir2=<local settings> \
|
--script_debug=_nix_ \
|
--rr=Server \
|
--rr_options=--chaos
|
|
Per first analysis of Marko fts_optimize_shutdown() should somehow wait that fts_optimize_callback() finishes.
|
Attachments
Issue Links
- is caused by
-
MDEV-16264 Implement a common work queue for InnoDB background tasks
-
- Closed
-
I did some rr replay debugging on this, setting watchpoints on the shadow bytes. The memory was allocated in:
bb-10.5-MDEV-15053-3 be3c9a23fd014ed80d48e2984dec78db921a7a00
#2 0x000055c750d3e40f in operator new(unsigned long) ()
from /usr/lib/x86_64-linux-gnu/libasan.so.4
#3 0x000055c74d8b6b09 in tpool::thread_pool_generic::create_timer (
this=0x616000024080, func=0x55c74d8103bd <timer_callback(void*)>, data=0x0)
at /home/mleich/bb-10.5-MDEV-15053-3/tpool/tpool_generic.cc:384
#4 0x000055c74d812c0c in fts_optimize_init ()
at /home/mleich/bb-10.5-MDEV-15053-3/storage/innobase/fts/fts0opt.cc:2964
#5 0x000055c74d485a25 in srv_start (create_new_db=false)
at /home/mleich/bb-10.5-MDEV-15053-3/storage/innobase/srv/srv0start.cc:1924
#6 0x000055c74d0014e0 in innodb_init (p=0x615000001e98)
at /home/mleich/bb-10.5-MDEV-15053-3/storage/innobase/handler/ha_innodb.cc:4001
#7 0x000055c74c52019a in ha_initialize_handlerton (plugin=0x62100002a410)
at /home/mleich/bb-10.5-MDEV-15053-3/sql/handler.cc:585
#8 0x000055c74bd926c6 in plugin_initialize (tmp_root=0x7ffd14278770,
plugin=0x62100002a410, argc=0x55c7502f1be0 <remaining_argc>,
argv=0x6150000005f8, options_only=false)
at /home/mleich/bb-10.5-MDEV-15053-3/sql/sql_plugin.cc:1459
#9 0x000055c74bd945ad in plugin_init (argc=0x55c7502f1be0 <remaining_argc>,
argv=0x6150000005f8, flags=0)
…
(rr) when
Current event: 6193
The memory was freed in:
bb-10.5-MDEV-15053-3 be3c9a23fd014ed80d48e2984dec78db921a7a00
#2 0x000055c750d3f28d in operator delete(void*) ()
from /usr/lib/x86_64-linux-gnu/libasan.so.4
#3 0x000055c74d8b6ae6 in tpool::thread_pool_generic::timer_generic::~timer_generic (this=0x6120000043c0, __in_chrg=<optimized out>)
at /home/mleich/bb-10.5-MDEV-15053-3/tpool/tpool_generic.cc:379
#4 0x000055c74d81317c in fts_optimize_shutdown ()
at /home/mleich/bb-10.5-MDEV-15053-3/storage/innobase/fts/fts0opt.cc:3017
#5 0x000055c74d486bab in srv_shutdown_bg_undo_sources ()
at /home/mleich/bb-10.5-MDEV-15053-3/storage/innobase/srv/srv0start.cc:2046
#6 0x000055c74d486cf3 in innodb_preshutdown ()
at /home/mleich/bb-10.5-MDEV-15053-3/storage/innobase/srv/srv0start.cc:2072
#7 0x000055c74c521fac in plugin_pre_shutdown (plugin=0x6030000114b8)
at /home/mleich/bb-10.5-MDEV-15053-3/sql/handler.cc:920
#8 0x000055c74bd9a1be in plugin_foreach_with_mask (thd=0x0,
func=0x55c74c521f44 <plugin_pre_shutdown(THD*, plugin_ref, void*)>,
type=1, state_mask=10, arg=0x0)
at /home/mleich/bb-10.5-MDEV-15053-3/sql/sql_plugin.cc:2470
#9 0x000055c74c521fd8 in ha_pre_shutdown ()
at /home/mleich/bb-10.5-MDEV-15053-3/sql/handler.cc:927
#10 0x000055c74ba648dd in mysqld_main (argc=38, argv=0x6150000005f8)
…
(rr) when
Current event: 866756
The invalid access was noticed shortly thereafter, at event 873535.
I believe that fts_optimize_shutdown() must ensure that the task for fts_optimize_callback() exits and will not be created, before deleting the timer. Or, we must defer the timer deletion to a later step at shutdown.