Slow-Query-Log

Das Slow-Query-Log von MariaDB lässt sich per Konfiguration aktivieren und erfasst Querys nach verschiedenen Kriterien. Die gängigste Variante ist das Logging aller Queries, die zur Ausführung länger als X Sekunden benötigt haben. Diese Variante lässt sich im Regelfall auch auf Produktiv-Servern problemlos einsetzen, ohne ein zu umfangreiches Logging zu erhalten.

# Time: 191016  6:28:55
# User@Host: user[user] @  [192.168.0.1]
# Thread_id: 243421041  Schema: myDatabase  QC_hit: No
# Query_time: 5.150556  Lock_time: 0.000130  Rows_sent: 3040  Rows_examined: 56703
# Rows_affected: 0  Bytes_sent: 34009
SELECT * FROM myTable WHERE z

Ein Auszug von wichtigen Informationen, die sich pro Slow-Query ablesen lassen, sind:

  • Query_time: Ausführungszeit der Query
  • Lock_time: In der Query_time enthaltene Wartezeit, die wegen Lockings gewartet werden musste
  • Rows_sent: Anzahl Zeilen die vom SQL-Server zum Client gesendet wurden
  • Rows_examined: Anzahl Zeilen, die für die Query-Ausführung untersucht werden mussten

Das Slow-Log kann über den Tag sehr stark anwachsen, sodass eine händische Auswertung schwierig wird.

mysqldumpslow

Ein einfaches Tool zur Auswertung ist mysqldumpslow. Es werden ähnliche Querys zusammengefasst und einfache Metriken aus dem Slow-Log ermittelt. Dazu gehören die Anzahl pro zusammengefasster Query sowie aggregierte und durchschnittliche Ausführungszeit, Locking-Zeit und Zeilenzahl.

Problematisch ist der Grad der Zusammenfassung. Strukturell gleiche Queries können als unterschiedlich erkannt werden, wenn z. B. die Anzahl der Parameter eines WHERE IN (…) unterschiedlich ist. Die Übersicht der Queries erfolgt so nicht optimal.

Ein Praxisbeispiel

Ein 61 MB großes Slow-Log wurde mit mysqldumpslow auf 43 MB zusammengefasst.
Die 43 MB sind nach wie vor eine zu große Datenmenge, um einfache Auswertungen machen zu können.

pt-query-digest

Das Konsolen-Tool pt-query-digest aus dem Percona Toolkit verfolgt einen ähnlichen Ansatz. Querys werden normalisiert und zusammengefasst.

Die Normalisierung geht allerdings weiter und kann die Struktur der Abfragen besser erkennen. Querys mit einer identischen Struktur erhalten einen eindeutigen Fingerprint und Querys mit gleichem Fingerprint werden in der Statistik zusammengefasst.

Weitere Möglichkeiten, die das Tool bietet: konfigurierbare Filter, hinzufügen von eigenen, abgeleiteten Kennzahlen, übersichtliche Statistiken und verschiedene Eingabequellen und Ausgabeformate.

Reports

Die Report-Ausgabe gliedert sich in drei wesentliche Bereiche.

Zu Beginn sieht man eine Zusammenfassung über alle ausgewerteten Querys. Numerische Attribute (z. B. Exec time, Lock time, Query size) werden mit Total, Min, Max, Durchschnitt, 95%-Grenze, Standardabweichung und Median angezeigt. Boolsche Informationen werden prozentual gegenübergestellt. In einem Überblick kann man so erkennen, ob es grobe Ausreißer gibt.

Als nächstes folgt eine Auflistung der Querys, die kumuliert die höchste Gesamtlaufzeit haben. Die Query-ID hilft dabei die eine Beispiel-Query im aktuellen Report zu finden.

Zudem kann man ein komplettes Slow-Log nach Querys mit der selben Query-ID durchsuchen. Eine Query-ID ist für strukturell gleiche Queries, unabhängig von den Parameter-Werten, gleich.

Im Anschluss gibt es für jede Query eine Übersicht, vergleichbar zur Gesamt-Übersicht. Hierbei werden allerdings ausschließlich Querys mit der selben ID betrachtet.

Konfiguration und Praxiseinsatz

Da pt-query-digest per Parameter konfigurierbar ist, bieten sich unterschiedliche Möglichkeiten zur Auswertung langsamer Abfragen. Es können gezielt Querys gesucht werden, die oft auftreten oder die z. B. eine bestimmte Größe von temporären Tabellen erzeugen.

Ein Praxiseinsatz bei uns hat dazu geführt, dass eine SQL-Query identifiziert werden konnte, die aus einem mehrere MB großen String bestand.

Neben dem reinen Text-Report bietet pt-query-digest die Möglichkeit an, die Ergebnisse in eine Datenbank zu schreiben. Dies kann zum einen als Historie genutzt werden und zum anderen eine Review-Funktionalität schaffen.