Bug #87301 innodb.trunc_multi_client_02 times out on server shutdown intermittently
Submitted: 3 Aug 2017 11:16 Modified: 4 Aug 2017 1:47
Reporter: Laurynas Biveinis (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:8.0.2 OS:Any
Assigned to: CPU Architecture:Any
Tags: innodb, mtr, purge

[3 Aug 2017 11:16] Laurynas Biveinis
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?
[3 Aug 2017 11:39] MySQL Verification Team
Hello Laurynas,

Thank you for the report.

Thanks,
Umesh
[4 Aug 2017 1:47] Erlend Dahl
The timeout has been increased in 8.0.3. That seems to have stabilized the test.