Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.2(EOL), 10.3(EOL), 10.4(EOL), 10.5, 10.6
Description
Occasionally, during a test that is restarting the server, a SIGABRT will be sent to the server even though there is no hang. I think that I have seen this happen on buildbot, but I do not know how to efficiently search for this in the cross-reference. The most recent occurrence was in a different CI environment:
|
mariadb-10.3.24 with some changes |
binlog_encryption.encryption_combo 'mix' w8 [ fail ] Found warnings/errors in server log file!
|
Test ended at 2020-08-18 13:32:30
|
line
|
Attempting backtrace. You can use the following information to find out
|
^ Found warnings in /var/tmp/mtr/8/log/mysqld.1.err
|
According to the server error log file, the signal is triggered during the second shutdown that the test is initiating (by executing the statement shutdown_server 10):
Version: '10.3.24-8-MariaDB-enterprise-log' socket: '/var/tmp/mtr/tmp/8/mysqld.1.sock' port: 16120 MariaDB Enterprise Server
|
2020-08-18 13:32:11 0 [Note] /home/jenkins/workspace/10.3e-DEV-NORMAL/BuildType/RelWithDebInfo/label/ubuntu-1804/bin/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown
|
2020-08-18 13:32:11 0 [Note] Event Scheduler: Purging the queue. 0 events
|
2020-08-18 13:32:11 0 [Note] InnoDB: FTS optimize thread exiting.
|
2020-08-18 13:32:11 0 [Note] InnoDB: Starting shutdown...
|
2020-08-18 13:32:11 0 [Note] InnoDB: Dumping buffer pool(s) to /var/tmp/mtr/8/mysqld.1/data/ib_buffer_pool
|
2020-08-18 13:32:11 0 [Note] InnoDB: Instance 0, restricted to 127 pages due to innodb_buf_pool_dump_pct=25
|
2020-08-18 13:32:11 0 [Note] InnoDB: Buffer pool(s) dump completed at 200818 13:32:11
|
2020-08-18 13:32:21 0 [Note] InnoDB: Shutdown completed; log sequence number 1629902; transaction id 28
|
200818 13:32:21 [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.3.24-8-MariaDB-enterprise-log
|
key_buffer_size=1048576
|
read_buffer_size=131072
|
max_used_connections=1
|
max_threads=153
|
thread_count=0
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63225 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 = 0x0 thread_stack 0x49000
|
2020-08-18 13:32:22 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
|
/home/jenkins/workspace/10.3e-DEV-NORMAL/BuildType/RelWithDebInfo/label/ubuntu-1804/bin/mysqld(my_print_stacktrace+0x2e)[0x55ec00bcaa7e]
|
mysys/stacktrace.c:271(my_print_stacktrace)[0x55ec00656775]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12890)[0x7fa061392890]
|
linux/futex-internal.h:88(futex_wait_cancelable)[0x7fa06138d9f3]
|
2020-08-18 13:32:22 0 [Note] /home/jenkins/workspace/10.3e-DEV-NORMAL/BuildType/RelWithDebInfo/label/ubuntu-1804/bin/mysqld: Shutdown complete
|
|
|
psi/mysql_thread.h:1177(inline_mysql_cond_wait)[0x55ec003bc6b1]
|
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xe7)[0x7fa060889b97]
|
/home/jenkins/workspace/10.3e-DEV-NORMAL/BuildType/RelWithDebInfo/label/ubuntu-1804/bin/mysqld(_start+0x2a)[0x55ec003ae5fa]
|
The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains
|
information that should help you find out what is causing the crash.
|
Writing a core file...
|
In the above output, we can see that the InnoDB shutdown almost completed within those 10 seconds. The last messages are interleaved with the stack trace output.
In the core dump, only two threads exist: the signal handler, and the main thread. The SIGABRT is delivered to the signal_hand() thread that is executing a syscall inside the following:
while ((error=my_sigwait(&set,&sig)) == EINTR) ; |
The mysqld_main() is waiting for that thread to terminate:
mysql_mutex_lock(&LOCK_thread_count);
|
while (!ready_to_exit) |
mysql_cond_wait(&COND_thread_count, &LOCK_thread_count);
|
mysql_mutex_unlock(&LOCK_thread_count);
|
I think that the 10-second timeout is unreasonably short for some CI environments. Many tests are using a 30-second timeout (which is on the border of being questionably short for debug builds), and the default timeout value is 60 seconds.
Since this change in MariaDB 10.3.1, shutdown timeouts will result in prominent failures, due to a SIGABRT being sent before a final SIGKILL.
Please fix all tests to use a more reasonable timeout than 10 seconds, and also consider replacing the 30-second timeouts with 60-second ones.
git grep -w shutdown_server
|
to find what to change.