[MDEV-22911] Fix the Valgrind & MSAN instrumentation of MDEV-8139 Created: 2020-06-16  Updated: 2020-06-16  Resolved: 2020-06-16

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.5
Fix Version/s: 10.5.4

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 0
Labels: None
Environment:

Valgrind build: Debian 9 Stretch, gcc 6.3.0, Valgrind 3.12.0.SVN

Issue Links:
Problem/Incident
is caused by MDEV-8139 Fix scrubbing Closed

 Description    

--source include/have_innodb.inc
 
 
 
SET FOREIGN_KEY_CHECKS= OFF;
 
CREATE TABLE t (f BLOB) ENGINE=InnoDB;
 
--error ER_FK_INCORRECT_OPTION
 
ALTER TABLE t ADD FOREIGN KEY (f) REFERENCES x (x);
 
 
 
# Cleanup
 
DROP TABLE t;

10.5 e290e5a7 Valgrind build, test ran with --valgrind

 
==3958== Thread 12:
 
==3958== Uninitialised byte(s) found during client check request
 
==3958==    at 0x12C2709: mtr_t::start() (mtr0mtr.cc:357)
 
==3958==    by 0x1596329: fil_names_clear(unsigned long, bool) (fil0fil.cc:4356)
 
==3958==    by 0x12987A0: log_checkpoint() (log0log.cc:1388)
 
==3958==    by 0x13FD270: srv_master_do_idle_tasks() (srv0srv.cc:1952)
 
==3958==    by 0x13FD66F: srv_master_callback (srv0srv.cc:2007)
 
==3958==    by 0x1637DAF: tpool::thread_pool_generic::timer_generic::run() (tpool_generic.cc:299)
 
==3958==    by 0x1637E9D: tpool::thread_pool_generic::timer_generic::execute(void*) (tpool_generic.cc:317)
 
==3958==    by 0x163CDCE: tpool::task::execute() (task.cc:52)
 
==3958==    by 0x163659F: tpool::thread_pool_generic::worker_main(tpool::worker_data*) (tpool_generic.cc:518)
 
==3958==    by 0x163C812: void std::__invoke_impl<void, void (tpool::thread_pool_generic::* const&)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(std::__invoke_memfun_deref, void (tpool::thread_pool_generic::* const&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&) (functional:227)
 
==3958==    by 0x163C784: std::result_of<void (tpool::thread_pool_generic::* const&(tpool::thread_pool_generic*&&, tpool::worker_data*&&))(tpool::worker_data*)>::type std::__invoke<void (tpool::thread_pool_generic::* const&)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(void (tpool::thread_pool_generic::* const&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&) (functional:251)
 
==3958==    by 0x163C718: decltype (__invoke((*this)._M_pmf, (forward<tpool::thread_pool_generic*>)({parm#1}), (forward<tpool::worker_data*>)({parm#1}))) std::_Mem_fn_base<void (tpool::thread_pool_generic::*)(tpool::worker_data*), true>::operator()<tpool::thread_pool_generic*, tpool::worker_data*>(tpool::thread_pool_generic*&&, tpool::worker_data*&&) const (functional:604)
 
==3958==    by 0x163C6CA: void std::_Bind_simple<std::_Mem_fn<void (tpool::thread_pool_generic::*)(tpool::worker_data*)> (tpool::thread_pool_generic*, tpool::worker_data*)>::_M_invoke<0ul, 1ul>(std::_Index_tuple<0ul, 1ul>) (functional:1391)
 
==3958==    by 0x163C5C8: std::_Bind_simple<std::_Mem_fn<void (tpool::thread_pool_generic::*)(tpool::worker_data*)> (tpool::thread_pool_generic*, tpool::worker_data*)>::operator()() (functional:1380)
 
==3958==    by 0x163C5A7: std::thread::_State_impl<std::_Bind_simple<std::_Mem_fn<void (tpool::thread_pool_generic::*)(tpool::worker_data*)> (tpool::thread_pool_generic*, tpool::worker_data*)> >::_M_run() (thread:197)
 
==3958==    by 0x647FE6E: ??? (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.22)
 
==3958==    by 0x4E3F4A3: start_thread (pthread_create.c:456)
 
==3958==    by 0x6D4BD0E: clone (clone.S:97)
 
==3958==  Address 0x128bca38 is on thread 12's stack
 
==3958==  in frame #1, created by fil_names_clear(unsigned long, bool) (fil0fil.cc:4344)
 
==3958== Thread 1:
 
==3958== Uninitialised byte(s) found during client check request
 
==3958==    at 0x12C2709: mtr_t::start() (mtr0mtr.cc:357)
 
==3958==    by 0x1596329: fil_names_clear(unsigned long, bool) (fil0fil.cc:4356)
 
==3958==    by 0x12987A0: log_checkpoint() (log0log.cc:1388)
 
==3958==    by 0x1298A65: log_make_checkpoint() (log0log.cc:1430)
 
==3958==    by 0x12997ED: logs_empty_and_mark_files_at_shutdown() (log0log.cc:1706)
 
==3958==    by 0x14077BD: innodb_shutdown() (srv0start.cc:2096)
 
==3958==    by 0x11BBD0D: innobase_end(handlerton*, ha_panic_function) (ha_innodb.cc:4086)
 
==3958==    by 0xD3AE24: ha_finalize_handlerton(st_plugin_int*) (handler.cc:562)
 
==3958==    by 0x9EE93B: plugin_deinitialize(st_plugin_int*, bool) (sql_plugin.cc:1262)
 
==3958==    by 0x9EEE69: reap_plugins() (sql_plugin.cc:1338)
 
==3958==    by 0x9F12EC: plugin_shutdown() (sql_plugin.cc:2019)
 
==3958==    by 0x88505F: clean_up(bool) (mysqld.cc:1984)
 
==3958==    by 0x88CCA5: mysqld_main(int, char**) (mysqld.cc:5647)
 
==3958==    by 0x88129F: main (main.cc:25)
 
==3958==  Address 0xffeffcab8 is on thread 1's stack
 
==3958==  in frame #1, created by fil_names_clear(unsigned long, bool) (fil0fil.cc:4344)

ASAN build on my local machine doesn't say anything, but here is related output from a remote box:

==5959==ERROR: LeakSanitizer: detected memory leaks
 
 
 
Indirect leak of 776 byte(s) in 2 object(s) allocated from:
 
    #0 0x7fc620b7bb80 in __interceptor_malloc (/usr/lib/x86_64-linux-gnu/libasan.so.4+0xdeb80)
 
    #1 0x1a5abee in ut_allocator<unsigned char, true>::allocate(unsigned long, unsigned char const*, unsigned int, bool, bool) /home/vsts/src/storage/innobase/include/ut0new.h:372
 
    #2 0x1a5abee in mem_heap_create_block_func(mem_block_info_t*, unsigned long, unsigned long) /home/vsts/src/storage/innobase/mem/mem0mem.cc:277
 
 
 
SUMMARY: AddressSanitizer: 776 byte(s) leaked in 2 allocation(s).
 
200616  2:48:13 [ERROR] mysqld got signal 6 ;
 
This could be because you hit a bug. It is also possible that this binary
 
or one of the libraries it was linked against is corrupt, improperly built,
 
or misconfigured. This error can also be caused by malfunctioning hardware.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
We will try our best to scrape up some info that will hopefully help
 
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
 
 
Server version: 10.5.4-MariaDB-log
 
read_buffer_size=131072
 
max_used_connections=3
 
thread_count=0
 
Thread pointer: 0x0
 
Attempting backtrace. You can use the following information to find out
 
where mysqld died. If you see no messages after this, something went
 
terribly wrong...
 
stack_bottom = 0x0 thread_stack 0x5fc00
 
??:0(__interceptor_sched_getaffinity)[0x7fc620af2900]
 
/home/vsts/server/bin/mariadbd(my_print_stacktrace+0xc6)[0x22509b6]
 
buf/buf0dblwr.cc:1118(buf_dblwr_t::write_single_page(buf_page_t*, bool, unsigned long))[0x10157e6]
 
??:0(__restore_rt)[0x7fc61f00b390]
 
linux/raise.c:54(__GI_raise)[0x7fc61e15d428]
 
stdlib/abort.c:91(__GI_abort)[0x7fc61e15f02a]
 
??:0(__sanitizer_cov_trace_pc_guard_init)[0x7fc620b9d76e]
 
??:0(__sanitizer_symbolize_global)[0x7fc620ba5558]
 
??:0(__lsan_enable)[0x7fc620ba97a2]
 
stdlib/cxa_finalize.c:60(__cxa_finalize)[0x7fc61e16236a]
 
/usr/lib/x86_64-linux-gnu/libasan.so.4(+0x20e43)[0x7fc620abde43]
 
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
 
information that should help you find out what is causing the crash.
 
Writing a core file...
 
Working directory at /dev/shm/var_auto_5nPZ/mysqld.1/data
 
Resource Limits:
 
ASAN:DEADLYSIGNAL
 
=================================================================
 
==5959==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000000 (pc 0x0000022494d4 bp 0x000000000003 sp 0x7fffacd27ef0 T0)
 
==5959==The signal is caused by a WRITE memory access.
 
==5959==Hint: address points to the zero page.
 
    #0 0x22494d3 in my_read /home/vsts/src/mysys/my_read.c:68
 
    #1 0x1014b9c in output_core_info /home/vsts/src/sql/signal_handler.cc:68
 
    #2 0x10156f5 in handle_fatal_signal /home/vsts/src/sql/signal_handler.cc:326
 
    #3 0x7fc61f00b38f  (/lib/x86_64-linux-gnu/libpthread.so.0+0x1138f)
 
    #4 0x7fc61e15d427 in gsignal (/lib/x86_64-linux-gnu/libc.so.6+0x35427)
 
    #5 0x7fc61e15f029 in abort (/lib/x86_64-linux-gnu/libc.so.6+0x37029)
 
    #6 0x7fc620b9d76d  (/usr/lib/x86_64-linux-gnu/libasan.so.4+0x10076d)
 
    #7 0x7fc620ba5557  (/usr/lib/x86_64-linux-gnu/libasan.so.4+0x108557)
 
    #8 0x7fc620ba97a1  (/usr/lib/x86_64-linux-gnu/libasan.so.4+0x10c7a1)
 
    #9 0x7fc61e162369 in __cxa_finalize (/lib/x86_64-linux-gnu/libc.so.6+0x3a369)
 
    #10 0x7fc620abde42  (/usr/lib/x86_64-linux-gnu/libasan.so.4+0x20e42)
 
 
 
AddressSanitizer can not provide additional info.
 
SUMMARY: AddressSanitizer: SEGV /home/vsts/src/mysys/my_read.c:68 in my_read
 
==5959==ABORTING

Valgrind part isn't reproducible on 10.4. I have no information about LeakSanitizer part.

Non-asan/valgrind build doesn't show any obvious problem right away.

Note: The error produced upon ALTER is questionable, I don't know if it should happen.



 Comments   
Comment by Elena Stepanova [ 2020-06-16 ]

Without disabling foreign keys Valgrind errors still occur, no information about LeakSanitizer, 

--source include/have_innodb.inc
 
 
 
CREATE TABLE t (f INT) ENGINE=InnoDB;
 
--error ER_CANT_CREATE_TABLE
 
ALTER TABLE t ADD FOREIGN KEY (f) REFERENCES x (x);
 
 
 
# Cleanup
 
DROP TABLE t;

Comment by Marko Mäkelä [ 2020-06-16 ]

I cannot reproduce the LeakSanitizer report with or without FOREIGN_KEY_CHECKS=OFF. I tried clang 10.0.0 Debug, and GCC 9.3.0 Debug and RelWithDebInfo.

--source include/have_innodb.inc
 
#SET FOREIGN_KEY_CHECKS= OFF;
 
CREATE TABLE t (f BLOB) ENGINE=InnoDB;
 
--error ER_FK_INCORRECT_OPTION,ER_CANT_CREATE_TABLE
 
ALTER TABLE t ADD FOREIGN KEY (f) REFERENCES x (x);
 
DROP TABLE t;

Comment by Elena Stepanova [ 2020-06-16 ]

As it was already discussed, I couldn't reproduce it locally either.
The environment where the LeakSanitizer error is happening is this:

  • Ubuntu Xenial x86_64;
  • a number of compilers is installed, including gcc-5.4.0 and gcc-7.5.0 with corresponding various versions of libasan; gcc-5.4.0 is Xenial's default;
  • during the ASAN build, gcc-7.5.0 is enabled through alternatives for the ASAN build;
  • when the server/test are run, gcc-5.4.0 is the default.

The cloud environment is not accessible for manual experiments, but I can set up tests to run something there if needed.

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