MySQL-Deadlock finden — Flamegraph ohne Profiling

Wir hatten ein seltsames Problem in einem unserer MySQL-Cluster: Die primäre Node konnte keine neuen Verbindungen mehr annehmen. Die Verbindungen wurden nicht abgelehnt, aber sie wurden auch nicht vollständig aufgebaut.

Ein Restart von mysqld hat das Problem gelöst – aber wir haben uns gefragt, was da passiert ist. Daher war eine der Maßnahmen im Post-Mortem, dass wir für die Zukunft dokumentieren, wie man Stacktrace aller MySQL-Threads dumpen kann.

Als das Problem kurz später noch mal auftrat, waren wir vorbereitet: Wir haben einen Coredump erstellt und uns dann mit gdb die Threads angesehen:

apt install gdb
gcore -o mysql.core $(pidof mysqld)

apt install mysql-community-server-core-dbgsym
gdb -ex 'thread apply all bt' -ex quit -batch /usr/sbin/mysqld ./mysql.core > mysql-bt.txt

Die Analyse

In der entstandenen Textdatei standen 587 Threads mit jeweils ihrem kompletten Stacktrace, ingesamt über 12.000 Zeilen – unangenehm viel, um sie alle durchzugucken, und zu unübersichtlich um zu versuchen ein Muster zu erkennen. Dann hatten wir eine Idee: es gibt Tooling um eine Sammlung von Stacktraces auszuwerten – aber aus dem Bereich der Performanceanalyse mit Profiling.

Flamegraphs sind eine von Performancemessungsguru Brendan Gregg erfundene Visualisierung. Man erfasst mit einem Profiler große Mengen Stacktraces und kann diese dann grafisch aufbereiten. Wir hatten eine kleine Menge Stacktraces – und nur an einem einzigen Zeitpunkt. Flamegraphs haben jedoch keine Zeitachse, sondern zählen einfach nur die Menge bestimmter Stackframes in den Samples.

Unsere Daten würden also funktionieren – wir mussten sie nur entsprechend aufbereiten. Praktischerweise kommt das Flamegraph-Toolkit bereits mit dem Programm stackcollapse-gdb.pl, welches das GDB-Format, was wir oben erzeugt haben, liest, und das nötige Format für flamegraph.pl ausgibt.

git clone https://github.com/brendangregg/FlameGraph.git
perl FlameGraph/stackcollapse-gdb.pl < mysql-bt.txt > mysql-stack.txt

Im Ausgabeformat ist jeder Stack nur eine einzige Zeile, in der alle Stackframes stehen, z.B.

clone3;start_thread;??;std::thread::_State_impl<std::thread::_Invoker<std::tuple<Detached_thread,;std::thread::_Invoker<std::tuple<Detached_thread,;std::thread::_Invoker<std::tuple<Detached_thread,;std::__invoke<Detached_thread,;std::__invoke_impl<void,;Detached_thread::operator()<void;std::invoke<void;std::__invoke<void;std::__invoke_impl<void,;fts_optimize_thread;ib_wqueue_timedwait;os_event_wait_time_low;os_event::wait_time_low;os_event::timed_wait;___pthread_cond_timedwait64;__pthread_cond_wait_common;__GI___futex_abstimed_wait_cancelable64;__futex_abstimed_wait_common;__futex_abstimed_wait_common64 1

Daraus können wir nun die Visualisierung erzeugen:

perl FlameGraph/flamegraph.pl < mysql-stack.txt > mysql-stack.svg 

Durch die Visualisierung kann man schnell sehen, dass die allermeisten Threads an der gleichen Stelle hängen: Acl_cache_lock_guard – das sieht verdächtig aus, als würden sie alle auf ein Lock warten. Das führt uns zur nächsten Frage: welcher Thread hält das Lock, und wieso gibt er es nicht frei?

Mit dem zeilenbasierten Format von stackcollapse können wir trivial mit grep die wartenden Threads ausfiltern und dann sehen wir nur noch die restlichen. Einer von ihnen wird vermutlich der sein, der das Lock hält.

grep -v Acl_cache_lock_guard mysql-stack.txt > mysql-filtered-stack.txt
perl FlameGraph/flamegraph.pl < mysql-filtered-stack.txt > mysql-filtered-stack.svg

Hier ergibt sich kein klares Bild mehr – aber wir haben nur noch 46 Stacks, die können wir von Hand durchlesen. Dabei sind uns dann 2 Threads ins Auge gesprungen (der Lesbarkeit halber etwas gekürzt):

mysql_execute_command;mysql_grant;log_and_commit_acl_ddl;acl_end_trans_and_close_tables;trans_commit_implicit;ha_commit_trans;MYSQL_BIN_LOG::commit;MYSQL_BIN_LOG::ordered_commit;MYSQL_BIN_LOG::change_stage;Commit_stage_manager::enroll_for;inline_mysql_cond_wait;my_cond_wait;native_cond_wait;___pthread_cond_wait

Im 1. Stack sehen wir „mysql_grant“ und andere Namen, die darauf hindeuten, dass hier etwas mit ACLs passiert. Beim Commit und Schreiben ins Binlog (MYSQL_BIN_LOG::commit) scheint er dann aber auf ein Lock zu warten (pthread_cond_wait).

mysql_execute_command;trans_commit;ha_commit_trans;MYSQL_BIN_LOG::commit;MYSQL_BIN_LOG::ordered_commit;call_after_sync_hook;Binlog_storage_delegate::after_sync;ReplSemiSyncMaster::commitTrx;inline_mysql_cond_timedwait;my_cond_timedwait;native_cond_timedwait;___pthread_cond_timedwait64

Im 2. Stack sehen wir ebenfalls das Binlog (MYSQL_BIN_LOG::commit) – evtl. gibt es also ein Lock fürs Schreiben ins Binlog, welches dieser Thread hält, und worauf der Thread mit mysql_grant wartet. Vor allem sehen wir hier aber ReplSemiSyncMaster::commitTrx – ein Indiz dafür, dass dieser Thread gerade auf die semi-synchrone Replication wartet, bevor er returnt. Ein Blick in den Code (die Datei und Zeilennummer steht im ursprünglichen Stacktrace) bestätigt das: „wait for the position to be ACK’ed back“. Hier wird also gewartet, dass die Replica bestätigt, dass sie die Transaktion erhalten hat.

Die Auflösung

Aus den Erkenntnissen formt sich eine Hypothese: MySQL wartet auf die Replication eines Commits. Es ist aber keine Replica verbunden, welche diese bestätigen kann. Gleichzeitig kann sich aber auch keine Replica mehr verbinden, weil neue Verbindungen ja hängen – wir haben also ein Deadlock.

Und tatsächlich, wenn man das Problem einmal verstanden hat, findet sich dann auch ein offener Bugreport bei MySQL zu diesem Thema: Can’t connect to MySQL with sync plugin enabled after user creation. Das Absurde daran ist, dass die User-Accounts in MySQL in InnoDB abgelegt werden, welches MVCC unterstützt – das Kernfeature von MVCC ist, dass sich Reads und Writes nicht blockieren. Leider tun sie es hier doch, weil MySQL zusätzlich ein Lock für die ACLs hat.

Wenn diese Analyse dein Interesse geweckt hat, interessieren dich vielleicht auch unsere Stellenangebote. 😉