Description:
Testcase innodb.trunc_multi_client_02 fails intermittently:
innodb_undo.trunc_multi_client_02 [ fail ]
Test ended at 2017-08-03 14:07:44
CURRENT_TEST: innodb_undo.trunc_multi_client_02
mysqltest: In included file ./include/restart_mysqld.inc at line 35:
included from ./suite/innodb_undo/include/undo_trunc_multi_client.inc at line 73:
included from /Users/laurynas/percona/mysql-8.0.2/mysql-test/suite/innodb_undo/t/trunc_multi_client_02.test at line 14:
At line 35: command "shutdown_server" failed with error 2. my_errno=175
Server error log then contains
1:07:29 UTC - 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.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.
key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=3
max_threads=151
thread_count=0
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 68254 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
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 = 0 thread_stack 0x46000
0 mysqld-debug 0x0000000102939de8 my_print_stacktrace + 88
1 mysqld-debug 0x00000001018dc821 handle_fatal_signal + 913
2 libsystem_platform.dylib 0x00007fffaa752b3a _sigtramp + 26
3 mysqld-debug 0x0000000102c1c58d ut_allocator<unsigned char>::get_mem_key(char const*) const + 221
4 libc++.1.dylib 0x00007fffa911b65b std::__1::this_thread::sleep_for(std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000000000l> > const&) + 80
5 mysqld-debug 0x0000000102be2050 void std::__1::this_thread::sleep_for<long long, std::__1::ratio<1l, 1000000l> >(std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000000l> > const&) + 1776
6 mysqld-debug 0x0000000102e988f1 srv_pre_dd_shutdown() + 993
7 mysqld-debug 0x0000000102c23e9e innodb_pre_dd_shutdown(handlerton*) + 30
8 mysqld-debug 0x0000000100d4f2db pre_dd_shutdown_handlerton(THD*, st_plugin_int**, void*) + 75
9 mysqld-debug 0x00000001012b1aea plugin_foreach_with_mask(THD*, bool (**)(THD*, st_plugin_int**, void*), int, unsigned int, void*) + 1770
10 mysqld-debug 0x00000001012b1c02 plugin_foreach_with_mask(THD*, bool (*)(THD*, st_plugin_int**, void*), int, unsigned int, void*) + 82
11 mysqld-debug 0x0000000100d4f27f ha_pre_dd_shutdown() + 47
12 mysqld-debug 0x0000000100ff2fd9 clean_up(bool) + 105
13 mysqld-debug 0x0000000100fe8e79 mysqld_main(int, char**) + 11561
14 mysqld-debug 0x0000000100b36922 main + 34
15 libdyld.dylib 0x00007fffaa543235 start + 1
16 ??? 0x000000000000000d 0x0 + 13
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
safe_process[90264]: Child process: 90265, killed by signal: 6
The "ut_allocator<unsigned char>::get_mem_key(char const*) const + 221" in the stacktrace above appears to be bogus.
A core dump loaded shows the following stacktrace instead:
* thread #1, stop reason = signal SIGSTOP
* frame #0: 0x00007fffaa671d42 libsystem_kernel.dylib`__pthread_kill + 10
frame #1: 0x00007fffaa75f457 libsystem_pthread.dylib`pthread_kill + 90
frame #2: 0x0000000102939f8b mysqld-debug`::my_write_core(sig=6) at stacktrace.cc:291
frame #3: 0x00000001018dcaa4 mysqld-debug`::handle_fatal_signal(sig=6) at signal_handler.cc:231
frame #4: 0x00007fffaa752b3a libsystem_platform.dylib`_sigtramp + 26
frame #5: 0x00007fffaa671f47 libsystem_kernel.dylib`__semwait_signal + 11
frame #6: 0x00007fffaa5f8b72 libsystem_c.dylib`nanosleep + 199
frame #7: 0x00007fffa911b65b libc++.1.dylib`std::__1::this_thread::sleep_for(std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000000000l> > const&) + 80
frame #8: 0x0000000102be2050 mysqld-debug`void std::__1::this_thread::sleep_for<long long, std::__1::ratio<1l, 1000000l> >(__d=0x00007fff5f0c3168) at thread:441
frame #9: 0x0000000102e988f1 mysqld-debug`srv_pre_dd_shutdown() at srv0start.cc:3031
frame #10: 0x0000000102c23e9e mysqld-debug`innodb_pre_dd_shutdown((null)=0x00007ff39c701780) at ha_innodb.cc:1498
frame #11: 0x0000000100d4f2db mysqld-debug`pre_dd_shutdown_handlerton((null)=0x0000000000000000, plugin=0x00007fff5f0c3568, (null)=0x0000000000000000) at handler.cc:1060
frame #12: 0x00000001012b1aea mysqld-debug`plugin_foreach_with_mask(thd=0x0000000000000000, funcs=0x00007fff5f0c3770, type=1, state_mask=4294967287, arg=0x0000000000000000)(THD*, st_plugin_int**, void*), int, unsigned int, void*) at sql_plugin.cc:2724
frame #13: 0x00000001012b1c02 mysqld-debug`plugin_foreach_with_mask(thd=0x0000000000000000, func=(mysqld-debug`pre_dd_shutdown_handlerton(THD*, st_plugin_int**, void*) at handler.cc:1057), type=1, state_mask=8, arg=0x0000000000000000)(THD*, st_plugin_int**, void*), int, unsigned int, void*) at sql_plugin.cc:2739
frame #14: 0x0000000100d4f27f mysqld-debug`ha_pre_dd_shutdown() at handler.cc:1068
frame #15: 0x0000000100ff2fd9 mysqld-debug`clean_up(print_message=true) at mysqld.cc:1927
frame #16: 0x0000000100fe8e79 mysqld-debug`mysqld_main(argc=70, argv=0x00007ff39c608a38) at mysqld.cc:6006
frame #17: 0x0000000100b36922 mysqld-debug`main(argc=13, argv=0x00007fff5f0c4680) at main.cc:25
frame #18: 0x00007fffaa543235 libdyld.dylib`start + 1
Printing "count" of srv_pre_dd_shutdown results in e.g. 565, corresponding to ~56.5 seconds spent in this function. This indicates that SIGABRT received is in fact the one sent by mysqltest on shutdown_server default timeout of 60 seconds. One of other threads in the core dump always shows purge in progress, it does not appear to be hung.
How to repeat:
Mac, CMake options for these particular runs are
-DBUILD_CONFIG=mysql_release -DWITH_DEBUG=ON -DWITH_ASAN=ON
-DWITH_BOOST=... -DWITH_OPENSSL=/path/to/homebrew/OpenSSL
-DWITH_ZLIB=system -DWITH_LZ4=system -DENABLE_DOWNLOADS=ON.
For core dumps tested with -DWITH_ASAN=ON removed from the above.
./mtr --debug-server trunc_multi_client_02 --big-test --repeat=100
Suggested fix:
Make purge faster? Increase shutdown timeout?