MySQL-Onlineprobleme mit langsamem Log und Optimierungslösungen

Das MySQL-Slow-Log ist ein Informationstyp, auf den MySQL-DBAs und anderes Entwicklungs- und Betriebspersonal besondere Aufmerksamkeit richten müssen. Mithilfe langsamer Protokolle können SQL-Anweisungen identifiziert werden, deren Ausführung lange dauert oder die Indizes nicht folgen. So entsteht eine Grundlage für die Systemoptimierung.

In diesem Artikel wird anhand eines Online-Falls analysiert, wie die MySQL-Slow-Log-Parameter richtig eingestellt und die Slow-Log-Funktion verwendet werden. Außerdem werden die Erweiterungen der MySQL-Slow-Log-Funktion durch NetEase Cloud RDS vorgestellt.

MySQL-Parametergruppenfunktionalität

NetEase Cloud RDS-Instanzen bieten Funktionen zur Parametergruppenverwaltung. Die am häufigsten verwendeten MySQL-Systemparameter können über die Parameterverwaltungsschnittstelle angezeigt werden. Benutzer können die aktuellen Betriebswerte und empfohlenen Werte verstehen:

Benutzer können die aufgelisteten Parameter auch über die Parameterverwaltungsseite ändern. Klicken Sie auf die Schaltfläche „Parameter ändern“, um sie online festzulegen. Klicken Sie auf „Änderungen speichern“, um die Parameteränderung der MySQL-Master- und Slave-Knoten mit einem Klick abzuschließen:

Anhand der Parameterverwaltungsschnittstelle lässt sich leicht feststellen, dass es viele Parameter gibt, die mit langsamen Abfragen in Zusammenhang stehen. Wie funktionieren diese Parameter? In welcher Beziehung stehen sie zueinander? Welche Bedingungen müssen erfüllt sein, damit SQL-Anweisungen im langsamen Protokoll aufgezeichnet werden? Nur wenn wir diese verstehen, können wir langsame Protokolle besser nutzen, um das System zu optimieren und Probleme zu lokalisieren.

Als Nächstes verwenden wir diesen Online-Fall als Referenz, um die korrekte Konfiguration langsamer Protokollparameter vorzustellen:

Einige Benutzer berichteten, dass die langsamen Protokolle mehrerer von ihnen verwendeter RDS 5.7-Instanzen ungewöhnlich waren. SQL-Anweisungen, deren Ausführung länger als eine Minute dauerte, wurden in den langsamen Protokollen nicht aufgezeichnet. Es werden auch SQL-Anweisungen zur Reproduktion bereitgestellt.

Richtige Konfiguration der Slow-Log-Parameter

Zuerst müssen wir bestätigen, ob die Slow-Log-Funktion für die Instanz aktiviert ist. Standardmäßig ist die MySQL-Slow-Log-Funktion deaktiviert. Der Schalterparameter für das langsame Protokoll ist slow_query_log, der in der Startbefehlszeile oder in der Konfigurationsdatei von mysqld explizit angegeben werden kann. Wenn slow_query_log=1 angegeben ist oder kein Wert angegeben wird, bedeutet dies, dass das langsame Protokoll eingeschaltet ist, und ein Wert von 0 bedeutet, dass es ausgeschaltet ist. Benutzer können es zur Laufzeit dynamisch ein- und ausschalten.

Die Slow-Log-Funktion ist für NetEase Cloud RDS-Instanzen standardmäßig aktiviert. Wir haben bestätigt, dass der Benutzer den Slow-Log-Schalter für die Instanz nicht ausgeschaltet hat.

Als Nächstes müssen Sie den Speicherort des Slow-Log-Datensatzes bestätigen. MySQL verwendet den Parameter log_output, um anzugeben, ob das Slow-Log in einer Datei (FILE) oder einer Tabelle (TABLE) gespeichert werden soll. Es sollte betont werden, dass nur durch die Angabe von log_output und das Setzen von slow_query_log auf 0 keine langsamen Protokolle aufgezeichnet werden. Mit anderen Worten: slow_query_log ist der Schalter für langsame Protokolle. Wenn Sie eine Datei zum Aufzeichnen langsamer Protokolle verwenden, können Sie den Dateinamen über slow_query_log_file angeben. Wenn der Benutzer slow_query_log_file nicht explizit angibt, initialisiert MySQL es mit host_name-slow.log, wobei host_name der Hostname ist, auf dem mysqld ausgeführt wird. Die langsame Protokolldatei befindet sich standardmäßig im MySQL-Datenverzeichnis.

NetEase Cloud RDS-Instanzen erlauben es Benutzern nicht, den Protokolldateipfad zu ändern, können jedoch den Parameter log_output konfigurieren. Durch Abfragen können Sie bestätigen, dass die Instanz langsame Protokolle in Dateien aufzeichnet. Überprüfen Sie die Protokolldateien, um sicherzustellen, dass keine SQL-Anweisungen wie vom Benutzer beschrieben vorhanden sind.

Da der Benutzer eine reproduzierbare Anweisung bereitgestellt hatte, führten wir die SQL-Anweisung aus und es dauerte tatsächlich mehr als eine Minute, bis sie zurückgegeben wurde. Durch den EXPLAIN-Befehl stellten wir fest, dass er den Index nicht durchlief und eine große Anzahl von Datensätzen scannte. Nachdem wir das langsame Protokoll erneut überprüft hatten, wurde die SQL-Anweisung immer noch nicht aufgezeichnet.

MySQL zeichnet SQL-Anweisungen auf, deren Ausführungszeit long_query_time in Sekunden überschreitet und deren Anzahl gescannter Datensätze min_examined_row_limit in Zeilen überschreitet.

Die Mindest- und Standardwerte des Parameters long_query_time betragen 1 bzw. 10 s. Der Parameter kann auf Mikrosekunden (ms) genau sein. Wenn Sie das Slow-Log in einer Datei aufzeichnen, ist die aufgezeichnete Zeit auf Mikrosekunden genau. Wenn Sie es in der Slow-Log-Tabelle (mysql.slow_log) aufzeichnen, ist es nur auf Sekunden genau und der Mikrosekundenteil wird ignoriert.

NetEase Cloud RDS-Instanzen ermöglichen es Benutzern, diese beiden Parameterwerte festzulegen. Hat der Benutzer also die beiden oben genannten Schwellenwerte angepasst, wodurch die Aufzeichnungsbedingungen nicht erfüllt wurden? Weitere Untersuchungen ergaben, dass dies nicht die Ursache des Problems war.

Wir haben festgestellt, dass MySQL auch einen Parameter namens log_queries_not_using_indexes hat, mit dem gesteuert wird, ob SQL-Abfragen protokolliert werden, die keine Indizes verwenden. Der Code lautet wie folgt:

Achten Sie besonders auf den durch den Pfeil angezeigten Inhalt. Wenn die Abfrage nicht über den Index geht oder der Index ungültig ist und die entsprechenden Parameter aktiviert sind, wird warn_no_index auf true gesetzt. Wenn die Anzahl der gescannten Datensätze gleichzeitig den Schwellenwert überschreitet, wird dies ebenfalls wie eine langsame Abfrage aufgezeichnet. Ist dieser Parameter also nicht aktiviert? Das Ergebnis ist immer noch negativ.

Die Ursache des Problems

Da es in der Datenbankinstanz viele SQL-Anweisungen geben kann, die keine Indizes verwenden, besteht bei aktiviertem log_queries_not_using_indexes die Gefahr eines schnellen Wachstums der Protokolldateien oder der Tabellenkapazität. In diesem Fall können Sie log_throttle_queries_not_using_indexes festlegen, um die Anzahl der SQL-Anweisungen zu begrenzen, die keine Indizes verwenden und pro Minute in das langsame Protokoll geschrieben werden. Der Standardwert dieses Parameters ist 0, was bedeutet, dass er nicht aktiviert ist, d. h. die Anzahl der geschriebenen SQL-Anweisungen wird nicht gesteuert.

Wenn diese Option aktiviert ist, öffnet das System nach der Ausführung der ersten Abfrage, die den Index nicht verwendet, ein 60-Sekunden-Fenster. Während dieses Fensters werden maximal log_throttle_queries_not_using_indexes-SQL-Anweisungen aufgezeichnet. Der Überschuss wird unterdrückt. Am Ende des Zeitfensters wird die Anzahl der im Fenster unterdrückten langsamen Abfragen und die Gesamtzeit, die für diese langsamen Abfragen aufgewendet wurde, ausgedruckt. Das nächste statistische Zeitfenster wird nicht sofort erstellt, sondern nach der Ausführung der nächsten Abfrage geöffnet, die den Index nicht verwendet.

Entsprechend diesem Online-Problem wird log_throttle_queries_not_using_indexes auf 10 gesetzt und der folgende Inhalt wird regelmäßig in die Protokolldatei gedruckt:

Dies stimmt tatsächlich mit dem oben beschriebenen Phänomen überein. Das langsame Protokoll des Benutzers sollte unterdrückt und in 359 zusammengefasst werden. Wir haben versucht, log_throttle_queries_not_using_indexes auf 0 zu setzen und dann die entsprechende SQL-Anweisung auszuführen. Tatsächlich wurde die entsprechende SQL-Anweisung in der Protokolldatei aufgezeichnet.

Dieses Online-Problem scheint lokalisiert worden zu sein. Das System generiert zu viele langsame Protokolle, die nicht indiziert sind, und der Satz log_throttle_queries_not_using_indexes ist zu klein, was dazu führt, dass die langsamen Protokolle, die nicht von Benutzern indiziert werden, nicht normal aufgezeichnet werden können. Aber es gibt noch ein Rätsel, das nicht gelöst wurde. Das heißt, wenn log_throttle_queries_not_using_indexes 0 ist, werden nicht mehr als 10 langsame Protokolle pro Minute gedruckt, ganz zu schweigen von den 359, die von Throttle angefordert werden. Wenn es also auf 10 eingestellt ist, sollte die vom Benutzer bereitgestellte SQL-Anweisung im langsamen Protokoll aufgezeichnet werden. Warum wird sie nicht aufgezeichnet? Was ist der Grund? Tatsächlich lässt sich die Antwort finden, indem man sich die Codelogik von MySQL-Protokollen, die keine Indizes verwenden, genau ansieht:

Die obige Abbildung zeigt die Hauptlogik der Aufzeichnung langsamer Protokolle. Ob Protokolle aufgezeichnet werden, wird durch die Funktion log_slow_applicable gesteuert. Ein Teil dieser Funktion wurde bereits zuvor analysiert. Schauen wir uns die anderen zugehörigen Inhalte dieser Funktion genauer an, wie in der roten Box in der folgenden Abbildung dargestellt:

Suppress_logging ist eine entscheidende Variable. Nur wenn sie false ist, kann das SQL-Statement aufgezeichnet werden. Das Ergebnis hängt mit log_throttle_queries_not_using_indexes zusammen. Schauen wir uns die Implementierung von log_throttle_qni.log genauer an, wie unten gezeigt:

Wählbar ist warn_no_index. Die Funktion inc_log_count() gibt true zurück, wenn die Gesamtzahl der Anweisungen, die innerhalb von 1 Minute keine Indizes verwenden, log_throttle_queries_not_using_indexes überschreitet. Nur wenn warn_no_index und inc_log_count() true zurückgeben, ist suppress_current true und suppress_current ist suppress_logging.

Durch die Analyse der beiden obigen Screenshots können wir die vorherigen Zweifel ausräumen:

log_throttle_queries_not_using_indexes zählt alle Anweisungen, die keine Indizes verwenden. Einige dieser Anweisungen werden nicht im Slow-Log aufgezeichnet, da sie die Beschränkung der Anzahl gescannter Datensätze nicht erfüllen. Aus diesem Grund sind bei einem Wert von 10 keine 10 Datensätze in der Slow-Log-Datei vorhanden. Dies liegt daran, dass 8 der 10 SQL-Anweisungen nicht aufgezeichnet wurden, da die Anzahl der gescannten Datensätze zu gering war.

Dies erklärt auch die Zahl 359 in der obigen Abbildung, nämlich die Gesamtzahl der SQL-Anweisungen, die den Index in diesem Zeitfenster nicht verwenden. Daher ist log_throttle_queries_not_using_indexes ein kritischer Parameter. Eine falsche Einstellung führt dazu, dass langsame Abfragen, die keine Indizes verwenden, nicht richtig aufgezeichnet werden, was zu einem teilweisen Ausfall der langsamen Protokollfunktion führt. Daher sollten Benutzer zunächst eine große Anzahl von SQL-Anweisungen, die keine Indizes verwenden, so weit wie möglich vermeiden. Sie können die Anweisungen mithilfe der RDS-Integritätsprüfungsfunktion optimieren. Zweitens: Wenn die oben genannten Eingabeaufforderungen im langsamen Protokoll angezeigt werden, sollte der Wert von log_throttle_queries_not_using_indexes erhöht werden, um das Problem weiter zu analysieren.

Erweiterung der InnoSQL-Slow-Log-Funktion

Einige Benutzer von RDS-Instanzen haben uns auch gefragt, warum die Ausführungszeit ihrer SQL-Anweisung die festgelegte long_query_time nicht überschritten hat und der Index nicht verwendet wurde, aber dennoch im Slow-Log aufgezeichnet wurde. Liegt hier ein Fehler vor? Tatsächlich handelt es sich hierbei nicht um einen Fehler. Dies liegt daran, dass die von NetEase Cloud RDS verwendete Version von InnoSQL (MySQL Open Source-Zweig, der von NetEase verwaltet wird) das langsame Protokoll optimiert hat. Neben der Überprüfung der Ausführungszeit der SQL-Anweisung wird auch auf die Anzahl der für die Abfrage erforderlichen Datenträgerseiten geachtet. Wenn die Anzahl der erforderlichen Seiten zu groß ist, kann dies auch größere Auswirkungen auf die Systemlast haben. Um die Statistiken zu quantifizieren, haben wir die Gesamtzahl der Seiten erfasst, die von der SQL-Abfrage gelesen werden müssen, sowie die Anzahl der tatsächlichen IOs, die auf diesen Seiten ausgeführt werden. Diese werden als logische Lesevorgänge bzw. physische Lesevorgänge aufgezeichnet. Erstere umfassen Seitenanforderungen, die den InnoDB-Pufferpool treffen, sowie solche, die fehlschlagen und IOs erfordern.

Diese Funktion wird Benutzern durch die Einführung von zwei Parametern bereitgestellt: slow_query_type und long_query_io. Ersterer ist auf 0/1/2/3 einstellbar. „1“ bedeutet, dass die langsame Protokollaufzeichnung basierend auf der Ausführungszeit aktiviert wird, „2“ bedeutet, dass die langsame Protokollaufzeichnung basierend auf der Gesamtzahl der durchsuchten Seiten erfolgt und „3“ ist eine Kombination aus „1“ und „2“. Daher kann in InnoSQL eine SQL-Abfrage nur dann im langsamen Protokoll aufgezeichnet werden, wenn die Ausführungszeit lang genug ist oder die Gesamtzahl der erforderlichen Seiten groß genug ist. Der Codeausschnitt lautet wie folgt:

Der Schwellenwert für die Seitenzahl wird durch den Parameter long_query_io gemessen, der vom Benutzer dynamisch festgelegt werden kann. Wenn die Gesamtzahl der Seiten m_logical_reads diesen Wert überschreitet, wird dies aufgezeichnet, auch wenn die Ausführungszeit den Grenzwert nicht überschreitet. Entsprechend werden der Slow-Log-Tabellenstruktur und dem Slow-Log-Dateiausgabeinhalt der RDS-Instanz neue Felder hinzugefügt.

Die obige Abbildung zeigt die InnoSQL-Version der slow_log-Tabellenstruktur, wobei logical_reads und physical_reads von InnoSQL hinzugefügte Felder sind. In ähnlicher Weise werden der Ausgabe der langsamen Protokolldatei zwei Felder hinzugefügt, wie unten gezeigt:

Zusätzlich zu der oben aufgeführten ausführlichen Beschreibung weist das MySQL-Slow-Log-Modul die folgenden erwähnenswerten Funktionen auf:

○ Die in den Slow-Log-Statistiken und Slow-Logs aufgezeichnete Zeit umfasst nicht die Wartezeit, die zum Erhalten der Sperre erforderlich ist, bevor mit der Ausführung der SQL-Anweisung begonnen wird.

○ MySQL schreibt SQL-Anweisungen erst dann in das Slow-Log, wenn sie ausgeführt wurden und alle Sperren aufgehoben wurden. Daher spiegelt die Reihenfolge, in der SQL-Anweisungen im Slow-Log aufgezeichnet werden, nicht genau die tatsächliche Ausführungsreihenfolge dieser SQL-Anweisungen wider.

○ Jedes Slow-Log enthält einen Zeitstempel. Wenn es in eine Datei geschrieben wird, wird der Parameter log_timestamps verwendet, um den Zeitstempel des Slow-Logs in die Zeit in der angegebenen Zeitzone umzuwandeln. Dieser Parameter hat jedoch keine Auswirkung auf die langsamen Protokolle in der Tabelle mysql.slow_log.

○ Sie können die langsame Protokollfunktion der MySQL-Slave-Bibliothek aktivieren, indem Sie log_slow_slave_statements festlegen.

○ Tabellenverwaltungsvorgänge wie ALTER TABLE, ANALYZE TABLE, CHECK TABLE, CREATE INDEX, DROP INDEX, OPTIMIZE TABLE und REPAIR TABLE können auch im langsamen Protokoll aufgezeichnet werden, das mit der Option log_slow_admin_statements aktiviert werden kann.