mariadb / gdb / debugging shutdown deadlock / part 1
I was asked to look into a MariaDB deadlock during shutdown. We had a core dump (luckily). Now it's time to dissect it.
Ensure you can get core dumps
For starters, you want a nice core dump whenever you hit an issue. We do. Here are some tips to ensure you do too.
You need to have a couple of parameters set correctly: the equivalent of
the systemd LimitCORE=infinity and the assurance that the working
directory is writable (maybe WorkingDirectory=/var/lib/mysql). And a
non-empty kernel.core_pattern (e.g. core.%p).
If MariaDB crashes, you get a core dump immediately. If it deadlocks,
you can kill it with SIGABRT to create one.
(Once you get a dump, it's nice to salvage it by moving it to less
volatile storage. This is especially important in a containerized
environment where the /var/lib/mysql can get flushed by a container
restart.)
Getting the symbols
Apart from gdb, the debugger, you'll also need the debug symbols. For
a Debian/Ubuntu install, you'll want to add these to your
sources.list:
deb http://ddebs.ubuntu.com jammy main restricted universe multiverse
deb http://ddebs.ubuntu.com jammy-updates main restricted universe multiverse
deb http://ddebs.ubuntu.com jammy-proposed main restricted universe multiverse
Or, if you're running packages from MariaDB directly:
deb [arch=amd64,arm64,ppc64el] http://archive.mariadb.org/mariadb-10.6.13/repo/ubuntu/ focal main
deb [arch=amd64,arm64,ppc64el] http://archive.mariadb.org/mariadb-10.6.13/repo/ubuntu/ focal main/debug
The main/debug component holds the dbgsym packages. This is also
the part where you ensure that you have the same MariaDB version (and
distro) as where the crash occurred. If you have different versions,
the core dump will make no sense at all.
Fetch at least these:
mariadb-server-10.6-dbgsym
mariadb-server-core-10.6-dbgsym
And confirm that they belong to the same binary version. It's also nice
to have libc6-dbg.
Firing up gdb
We have gdb. We have symbols. We have a core dump. Fire it up:
$ gdb /usr/sbin/mariadbd core.208161
...
Core was generated by `/usr/sbin/mysqld --defaults-file=/etc/mysql/my.cnf --wsrep_start_position=73'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0 0x00007f700639c3db in kill () at ../sysdeps/unix/syscall-template.S:78
78 ../sysdeps/unix/syscall-template.S: No such file or directory.
[Current thread is 1 (Thread 0x7f70061c3840 (LWP 208161))]
(gdb)
At this point, we can do the usual stuff: bt, bt full,
info threads, thread apply all bt full, info regs and so on.
In this case, we were stuck in shutdown. This is confirmed by the first thread we look at:
(gdb) bt
#0 0x00007f700639c3db in kill () at ../sysdeps/unix/syscall-template.S:78
#1 0x0000559aca322bae in handle_fatal_signal (sig=11) at ./sql/signal_handler.cc:372
#2 <signal handler called>
#3 0x00007f700643623f in __GI___clock_nanosleep () at ../sysdeps/unix/sysv/linux/clock_nanosleep.c:78
#4 0x00007f700643bec7 in __GI___nanosleep () at nanosleep.c:27
#5 0x00007f700643bdfe in __sleep (seconds=0, seconds@entry=1) at ../sysdeps/posix/sleep.c:55
#6 0x0000559aca5ea13a in wsrep_close_client_connections (wait_to_end=<optimized out>, except_caller_thd=0x0) at ./sql/wsrep_mysqld.cc:3253
#7 0x0000559aca5ea83a in wsrep_shutdown_replication () at ./sql/wsrep_mysqld.cc:1150
#8 0x0000559aca00f7dd in mysqld_main (argc=<optimized out>, argv=<optimized out>) at ./sql/mysqld.cc:5899
#9 0x00007f700637d083 in __libc_start_main (main=0x559ac9fbecb0 <main(int, char**)>, argc=3, argv=0x7ffdd3be23c8, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffdd3be23b8) at ../csu/libc-start.c:308
#10 0x0000559aca00300e in _start () at ./include/mysql/plugin.h:215
The code appeared to be busy in a sleep(0).
It's best to have the MariaDB 10.6.13 source code checked out
somewhere. Git clone the entire repository, check out the correct tag,
and get those git submodules. There you can now find
./sql/wsrep_mysqld.cc:3253, which lists:
void wsrep_close_client_connections(my_bool wait_to_end, THD* except_caller_thd)
{
// ...
while (wait_to_end && server_threads.iterate(have_client_connections))
{
sleep(1);
DBUG_PRINT("quit",("One thread died (count=%u)", THD_count::value()));
}
Yes, it is in fact sleep(1) not 0 — and now that you mention it,
it did say seconds@entry=1:
(gdb) up 6
#6 0x0000559aca5ea13a in wsrep_close_client_connections () at ./sql/wsrep_mysqld.cc:3253
3253 ./sql/wsrep_mysqld.cc: No such file or directory.
(gdb) disass
Dump of assembler code for function wsrep_close_client_connections(char, THD*):
Address range 0x559aca5e9dc0 to 0x559aca5ea3fb:
...
0x0000559aca5ea12b <+875>: callq 0x559ac9f54150 <pthread_rwlock_unlock@plt>
0x0000559aca5ea130 <+880>: mov $0x1,%edi
0x0000559aca5ea135 <+885>: callq 0x559ac9f54080 <sleep@plt>
=> 0x0000559aca5ea13a <+890>: jmpq 0x559aca5ea080 <wsrep_close_client_connections(char, THD*)+704>
0x0000559aca5ea13f <+895>: nop
0x0000559aca5ea140 <+896>: cmpq $0x0,(%r14)
0x0000559aca5ea144 <+900>: jne 0x559aca5ea240 <wsrep_close_client_connections(char, THD*)+1152>
(That mov $0x1,%edi puts 1 into the first argument — RDI, RSI,
RDX, RCX, R8, R9 — and then sleep is called. See the System V amd64
calling
convention.)
Inspecting server_threads.iterate
So, wsrep_close_client_connections is looping until
server_threads.iterate(have_client_connections) returns zero.
static my_bool have_client_connections(THD *thd, void*)
{
DBUG_PRINT("quit",("Informing thread %lld that it's time to die",
(longlong) thd->thread_id));
if (is_client_connection(thd) &&
(thd->killed == KILL_CONNECTION ||
thd->killed == KILL_CONNECTION_HARD))
{
(void)abort_replicated(thd);
return 1;
}
return 0;
}
Assuming that server_threads.iterate iterates over the server threads,
we can conclude that one or more threads are (a) a client connection and
(b) in some kind of "KILL" state and (c) receiving an
abort_replicated(thd) call.
(gdb) ptype server_threads
type = class THD_list : public THD_list_iterator {
public:
void init(void);
void destroy(void);
void insert(THD *);
void erase(THD *);
}
server_threads is a global. It inherits from the
THD_list_iterator. If we look there, we see this:
/** THD registry */
class THD_list_iterator
{
// ...
template <typename T> int iterate(my_bool (*action)(THD *thd, T *arg), T *arg= 0)
{
int res= 0;
mysql_rwlock_rdlock(&lock);
I_List_iterator<THD> it(threads);
while (auto tmp= it++)
if ((res= action(tmp, arg)))
break;
mysql_rwlock_unlock(&lock);
return res;
}
So, server_threads.iterate iterates over all threads and stops as soon
as it finds one with the previously mentioned characteristics, returning
the (boolean) value of the callback.
Figuring out which threads were doing what
We want to know what those unstopped threads were doing. If we could get
a SHOW PROCESSLIST from the dead process, that'd be perfect. Maybe we
can iterate over the server_threads and get the info.
(gdb) print server_threads->threads
$1 = {
<base_ilist> = {
first = 0x7f5080046088,
last = {_vptr.ilink = 0x559acaf1b670 <vtable for ilink+16>, prev = 0x7f6360000c68, next = 0x0}},
<No data fields>
}
(gdb) print server_threads.threads.first
$2 = (ilink *) 0x7f5080046088
(gdb) print *server_threads.threads.first
$3 = {_vptr.ilink = 0x559acaf21550 <vtable for THD+16>, prev = 0x559acb121b00 <server_threads>, next = 0x7f4fc4000c58}
This is a linked list structure, wrapped in a bit of C++ sauce.
We can in fact get the elements out of it fairly easily:
(gdb) print *(THD*)server_threads.threads.first
$5 = {
<THD_count> = {
static count = {
m_counter = {
...
(gdb) print ((THD*)server_threads.threads.first)->proc_info
$5 = 0x559aca9152dc "Freeing items"
And we can continue with the next items:
(gdb) print ((THD*)server_threads.threads.first->next)->proc_info
$6 = 0x559aca922c02 "committing"
That's nice. But tedious. We don't want to do this for every thread — there could be many.
Luckily gdb has builtin Python support. And that's what we'll be looking at in the next post...