MySQL Replication Monitoring
Vor einigen Tagen verloren nach einem Failover auf die Hot-Standby-Maschine ein Großteil dort aktiven Kunden ihre Kommunikationsmöglichkeit. Grund waren divergierende MySQL-Datenbanken, die eigentlich per Replikation in einem synchronen Zustand gehalten werden. Derartige Fehlerzustände werden überwacht und ggf. alarmiert. Aber genau das Monitoring hat versagt.
Was geschehen ist
Eine Appliance für einen klassischen Cloud-Dienst, steht als Hochverfügbarkeitslösung mit zwei Knoten da, von denen der eine den anderen in Sekundenbruchteilen übernehmen kann. Alle laufenden Sessions der Kunden werden dabei übernommen, so dass der Kunde nichts vom Umschalten mit bekommt.
Das hat jahrelang bestens geklappt. Nur eben diesmal nicht. Die Lösung des Problems war einfach: Zurückschalten und Beginn der Fehleranalyse.
Es stellte sich heraus, dass die MySQL-Datenbank auf dem Standby-System schon seit Tagen nicht mehr synchron lief. Sie verweigerte ab einem bestimmten Kommando (Löschen einer Tabelle) das Replay des Replikationslogs. Grund war, dass die Tabelle selbst schon nicht vorhanden war und deswegen nicht gelöscht werden konnte. Die Tabelle selbst war nur ein Überbleibsel eines Tests, also nicht wirklich relevant. Warum sie auf dem zweiten System schon gefehlt hat, ist nicht ganz nachvollziehbar. Vermutlich hat sich irgendwann der Replikations-Filter geändert, so dass die Tabelle erst später Bestandteil der Replikation wurde.
Fakt ist, dass die Replikation nicht mehr lief. Beim Failover traten dann die abstrusesten Effekte auf.
Warum es nicht auffiel
Wesentlich interessanter ist die Frage, warum die fehlerhafte Synchronisation nicht aufgefallen ist. Schließlich gibt es ein Monitoring auf Synchronisations-Diskrepanzen an die ein Alarm angeschlossen ist. Eigentlich hätte es also schon Tage vorher mächtig klingeln sollen.
Das Monitoring lieferte aber immer nur einen Wert von "0" für die Anzahl der Synchronisationsabweichungen. Warum?
Ein Blick in den Quellcode des Monitorings (ein collectd-Plugin) zeigt:
if ($MK_REPLICATE_CHECK_TABLES && $MK_REPLICATE_CHECK_HOSTS) {
my $now = time();
my $fake;
if ($MK_REPLICATE_CHECK_INTERVAL && $mk_last_run && defined($mk_last_result)) {
if ($now - $mk_last_run < $MK_REPLICATE_CHECK_INTERVAL) {
$fake = $mk_last_result;
}
}
if (!defined($fake)) {
my @tables = split(/[\s,;]+/, $MK_REPLICATE_CHECK_TABLES);
my @fails = do_replication_check(\@tables);
my @rechecks = do_replication_check(\@fails, '--wait=60');
$fake = scalar(@rechecks);
$mk_last_run = $now;
$mk_last_result = $fake;
}
defined($fake) and plugin_dispatch_values({
type => 'mysql_replication_discrepancies',
plugin => "XXX",
values => [ $fake ],
host => $ME,
});
} Collectd ruft eine read-Funktion regelmäßig auf, um dem Plugin die Möglichkeit zu geben, Daten zu sammeln. Hat das Plugin die Daten ermittelt, schickt es diese mit plugin_dispatch_values an den collectd zurück, der den Messwert an die verschiedenen write-Funktionen der Ausgabe-Plugins übermittelt. Letzteres ist u.a. der RRD-Writer.
In diesem Fall fällt auf, dass das Plugin nur alle $MK_REPLICATE_CHECK_INTERVAL Sekunden überhaupt eine Messung macht. In der Zwischenzeit liefert es den letzten Messwert immer wieder aus.
Weiterhin auffällig ist, dass der Messwert selbst die Anzahl der Tabellen enthält, die nicht synchron sind. Dazu übergibt er die zu überwachenden Tabellen der eigentlichen Messfunktion und diese liefert ihm die Liste der Tabellen, die nicht synchron sind.
In einer zweiten Runde werden – mit einer Wartezeit von bis zu einer Minute – die Tabellen angeschaut, die sich verändert haben. I.d.R. also die Tabellen, die häufigen Änderungen unterliegen. Diese werden nach einem deutlich aufwendigeren Verfahren auf Synchronität untersucht. Es ist offenbar sinnvoll, die statischen Tabellen in einer schnellen ersten Runde schon auszusortieren.
Was dann immer noch nicht synchron ist, bleibt übrig und erhöht den Rückgabewert um eins.
Dieser Teil der Funktion schaut auf den ersten Blick ganz normal aus.
Wie funktioniert aber nun die Messung?
Die eigentliche Messfunktion ist folgende:
sub do_replication_check {
my ($tables, $add_args) = @_;
$add_args or $add_args = '';
my %results;
for my $t (@$tables) {
my $arg = ($t =~ /\./) ? "--tables=$t" : "--databases=$t";
my $out = `mk-table-checksum --algorithm=ACCUM $arg $add_args --tab $MK_REPLICATE_CHECK_HOSTS 2>&1`;
my @out = split(/[\n\r]+/, $out);
my @headers = split(/\t/, $out[0]);
for my $i (1 .. $#out) {
$out[$i] or next;
my @c = split(/\t/, $out[$i]);
scalar(@c) == scalar(@headers) or next;
my $h = { map {$headers[$_], $c[$_]} (0 .. $#headers) };
$results{$h->{DATABASE} . '.' . $h->{TABLE}}->{$h->{HOST}} = $h;
}
}
my @fails;
for my $k (values(%results)) {
ref($k) eq 'HASH' or next;
my @r = values(%$k);
@r > 1 or next;
my $h = $r[0]->{CHECKSUM};
for my $j (1 .. $#r) {
my $i = $r[$j];
$h eq $i->{CHECKSUM} and next;
push(@fails, $i->{DATABASE} . '.' . $i->{TABLE});
last;
}
}
return @fails;
}Man kann sicher über den Stil der Perl-Programmierung lästern, aber das ist nicht das Thema. Interessanter ist die Frage, was der Code tut.
Er lässt sich vom Programm mt-table-checksum die Liste der Prüfsummen über die einzelnen Tabellen geben. Diese parst er und vergleicht anschließend, ob die Prüfsummen pro gefundener Tabelle auf beiden Systemen überein stimmt.
Hat er unterschiedliche Prüfsummen für die Tabellen gefunden, so wird die Tabelle als unsynchronisiert zurück gemeldet.
Was kann daran schon schief gehen?
Ich schaue mir die Ausgabe des Programms mal direkt an:
# mt-table-checksum ... -bash: mt-table-checksum: command not found
WTF?!
Der Programmcode ignoriert die erste Zeile (die mit der Fehlermeldung) und liest dann die Liste der Tabellen mit ihren Prüfsummen ein (die ist leer). Anschließend vergleicht er, ob er für die gefundenen Tabellen (also keine) Unterschiede bei den Prüfsummen feststellen kann (was nicht möglich ist). Also kommt er zum Schluss, dass keine Unterschiede vorliegen.
Keine Unterschiede zwischen den beiden MySQL-Instanzen heißt also, nach Logik des darüber liegenden Monitorings, dass die Synchronisation in Ordnung ist.
Was wirklich schief gelaufen ist
Der eigentliche Fehler der Messfunktion besteht darin, dass sie keine Validitätsprüfung der Ausgabe gemacht hat.
Sie bekommt eine Liste von Tabellen und hat dann zumindest zu prüfen, ob diese Tabellen überhaupt Prüfsummen geliefert haben! Würde das geprüft, wäre das Fehlen des externen Programms instantan aufgefallen.
Man kann natürlich auch argumentieren, dass der Errorcode des Programmaufrufs zu prüfen gewesen wäre. Oder die Existenz des Programms selbst. Oder, oder ... Am Ende läuft es darauf hinaus, dass die erwartete Ausgabe vorliegt. Schließlich gibt es ja auch noch viele andere Möglichkeiten, warum das externe Programm seinen Job nicht erledigen konnte.
Es wäre nun leicht, diesen Test hinzu zufügen. Allerdings ist das eine fremde Appliance und da geht der Weg über den Hersteller-Support.
Was wir tun können, ist das fehlende Programm nachzuinstallieren. Es ist im Rahmen eines Updates verschwunden, als die Datenbank dieses Programm durch das wesentlich flexiblere und robustere pt-table-checksum ersetzt hat. Ja, das ist schon eine ganze Weile her.
Überraschende Nicht-Lösung
Nachdem nun das betreffende Programm mk-table-checksum installiert war (wobei der Alarm an sprang) und manuell die Datenbank wieder in Sync gebracht wurde (so dass der Alarm verstummte), schien alles soweit in Butter.
Allerdings zeigte sich in der darauf folgenden Nacht, dass da noch ein anderer Fehler drin steckt.
Über einige Stunden schwankte der Messwert, den collectd einsammelte, zwischen 0.1666, 0.25, 0.3333 und 0.5. Alle paar Minuten ergab sich ein anderer Wert.
Zur Erinnerung: Der Messwert ist die Anzahl der unsynchronisierten Tabellen!
Erst die Dokumentation von collectd brachte die Lösung: Wenn mehrere Messwerte in einem sehr kurzen Zeitfenster eingehen, werden sie von collectd gemittelt und dieser Mittelwert wird an die write-Funktionen übermittelt. Die Messwerte sind klare Brüche: Einer von zwei, drei, vier, ... Messungen hatte eine Eins, der Rest Null geliefert.
Wie können aber viele Messwerte in so kurzer Zeit eingehen?
Zur Erinnerung: collectd ruft die read-Funktion regelmäßig auf. Also auch dann, wenn die schon aufgerufene Funktion sich noch nicht beendet hat!
Es liefen also zwei oder mehr Prüfungen parallel. Und vermutlich war zu dem Zeitpunkt die Datenbank mächtig belastet. Es hat alles gedauert, auch die Tests. Als die Last nachließ, wurden alle Prüfungen zusammen fertig.
Logischerweise hinkt eine schwer belastete Datenbank auch in der Replikation hinterher. Es ist also nur natürlich, wenn einer der Messungen dieses feststellt.
Also Ticket Nummer zwei beim Hersteller: Verhindern der Doppelausführung.