Slow Query Log systematisch auswerten statt nur aktivieren

1. Slow Query Log aktivieren

Der Slow Query Log von MySQL protokolliert jede Anfrage, deren Ausführungszeit einen definierten Schwellenwert überschreitet, zusammen mit Metadaten wie der Ausführungszeit, der Anzahl gesperrter Zeilen und der Anzahl untersuchter Datensätze. Aktiviert wird er über die Variablen slow_query_log = 1 und slow_query_log_file, wobei der Zielpfad auf ein Verzeichnis mit ausreichend Speicherplatz und angemessenen Schreibrechten für den MySQL-Prozess zeigen muss. Beide Variablen lassen sich sowohl in der my.cnf dauerhaft als auch zur Laufzeit über SET GLOBAL setzen, letzteres ohne Server-Neustart, was für gezielte Diagnose-Sessions praktisch ist.

Ein häufiger Fehler ist, den Slow Query Log zu aktivieren und danach zu vergessen, ihn systematisch auszuwerten. Die Datei wächst dann unkontrolliert, ohne dass jemand die enthaltenen Informationen nutzt, bis irgendwann der Speicherplatz knapp wird oder ein Incident die Datei erst ins Bewusstsein bringt. Der Slow Query Log entfaltet seinen Wert erst durch regelmäßige, strukturierte Auswertung, nicht durch bloßes Vorhandensein. Ein Rotationsschema und ein wiederkehrender Auswertungsprozess sollten daher von Anfang an mitgeplant werden, nicht erst nach dem ersten Performance-Vorfall.

Zusätzlich zur reinen Aktivierung empfiehlt sich das Log-Ausgabeformat log_output = FILE statt TABLE, da die dateibasierte Variante von externen Analysewerkzeugen wie pt-query-digest direkt gelesen werden kann, während die Tabellen-Variante zusätzliche Overhead-Schreibzugriffe auf die Systemtabelle mysql.slow_log erzeugt. Für produktive Instanzen mit hoher Last ist die dateibasierte Protokollierung fast immer die bessere Wahl.

-- Enable the slow query log at runtime (no restart needed)
SET GLOBAL slow_query_log = 'ON';
SET GLOBAL slow_query_log_file = '/var/log/mysql/slow-query.log';
SET GLOBAL log_output = 'FILE';

-- Verify current status
SHOW VARIABLES LIKE 'slow_query_log%';
-- +---------------------+-------------------------------+
-- | Variable_name       | Value                         |
-- +---------------------+-------------------------------+
-- | slow_query_log      | ON                            |
-- | slow_query_log_file | /var/log/mysql/slow-query.log |
-- +---------------------+-------------------------------+

2. long_query_time richtig wählen

Die Variable long_query_time bestimmt in Sekunden, ab welcher Ausführungsdauer eine Anfrage als langsam gilt und in den Slow Query Log aufgenommen wird. Der Standardwert von 10 Sekunden ist für die meisten modernen Webanwendungen viel zu hoch angesetzt, denn eine Anfrage, die drei Sekunden benötigt, ist für einen Onlineshop bereits katastrophal langsam und würde bei diesem Default niemals im Log auftauchen. Für produktive Systeme hat sich ein Wert zwischen 0,1 und 1 Sekunde als praxistauglicher Ausgangspunkt etabliert, abhängig vom Charakter der Anwendung.

Ein zu niedriger Schwellenwert, etwa 0,01 Sekunden auf einem stark frequentierten System, führt jedoch zum gegenteiligen Problem, der Slow Query Log wächst dann so schnell, dass die eigentlich relevanten langsamen Anfragen im Rauschen unauffälliger, aber häufiger Anfragen untergehen. Ein iteratives Vorgehen bewährt sich: zunächst mit einem moderaten Wert wie 0,5 Sekunden starten, die Ergebnisse auswerten, und dann je nach Datenmenge und Aussagekraft schrittweise absenken, bis das Verhältnis aus Informationsgehalt und Log-Volumen stimmt.

Für einmalige, tiefgehende Diagnose-Sessions kann long_query_time temporär auf einen sehr niedrigen Wert wie 0 gesetzt werden, um faktisch jede Anfrage zu protokollieren, kombiniert mit log_slow_admin_statements für administrative Befehle. Das erzeugt naturgemäß ein großes Datenvolumen und sollte nur für einen begrenzten Zeitraum unter Beobachtung aktiv bleiben, niemals dauerhaft in der Produktion.

-- Iterative tuning: start moderate, then narrow down
SET GLOBAL long_query_time = 0.5;   -- catches anything slower than 500ms
-- After reviewing results for a day, tighten further if the volume is manageable
SET GLOBAL long_query_time = 0.2;   -- catches anything slower than 200ms

-- Temporary deep diagnostic session (short window only!)
SET GLOBAL long_query_time = 0;
SET GLOBAL log_slow_admin_statements = 'ON';
-- ... run the diagnostic window for a few minutes, then revert:
SET GLOBAL long_query_time = 0.5;

3. log_queries_not_using_indexes und weitere Parameter

Neben der reinen Zeitschwelle bietet MySQL zusätzliche Parameter, die den Slow Query Log gezielt erweitern. log_queries_not_using_indexes = 1 protokolliert jede Anfrage, die keinen Index nutzt, unabhängig von ihrer Ausführungszeit. Das ist besonders wertvoll, weil eine Anfrage auf einer aktuell kleinen Tabelle ohne Index heute schnell genug sein kann, aber bei wachsender Datenmenge zum Problem wird, lange bevor sie die reguläre Zeitschwelle überschreitet.

Der Parameter min_examined_row_limit filtert Anfragen, die zwar lange dauern, aber nur wenige Zeilen untersuchen, häufig ein Zeichen für externe Faktoren wie Lock-Wartezeiten statt echter Query-Ineffizienz. Umgekehrt hilft log_throttle_queries_not_using_indexes ab MySQL 5.7, die Flut identischer Warnungen für dieselbe ungeindexte Anfrage zu begrenzen, statt bei jeder Ausführung erneut einen vollständigen Eintrag zu erzeugen. Diese Feinsteuerung verhindert, dass der Slow Query Log durch redundante Einträge unübersichtlich wird.

# my.cnf: recommended slow query log configuration for production
[mysqld]
slow_query_log = 1
slow_query_log_file = /var/log/mysql/slow-query.log
long_query_time = 0.5
log_queries_not_using_indexes = 1
log_throttle_queries_not_using_indexes = 60
min_examined_row_limit = 100
log_output = FILE

4. pt-query-digest: Aggregation und Priorisierung

Ein roher Slow Query Log mit tausenden Einträgen ist für einen Menschen kaum manuell auswertbar. pt-query-digest aus dem Percona Toolkit normalisiert die Anfragen, indem es Literale durch Platzhalter ersetzt, gruppiert strukturell identische Anfragen zusammen und sortiert die Ergebnisse standardmäßig nach der Gesamtzeit, die eine Query-Klasse über alle Ausführungen hinweg beansprucht hat. Das ist der entscheidende Unterschied zur reinen Betrachtung der langsamsten Einzelanfrage, denn eine Anfrage, die 50 Millisekunden dauert, aber zehntausendmal pro Stunde ausgeführt wird, hat oft einen größeren Gesamteinfluss als eine einzelne Fünf-Sekunden-Anfrage, die nur einmal täglich läuft.

Die Ausgabe von pt-query-digest liefert für jede Query-Klasse Kennzahlen wie Anzahl der Ausführungen, minimale, durchschnittliche und maximale Ausführungszeit, sowie die Summe aller untersuchten Zeilen. Diese aggregierte Sicht ist der eigentliche Wert des Tools, weil sie eine objektive, datenbasierte Priorisierung ermöglicht, statt sich auf subjektive Vermutungen zu verlassen, welche Anfrage wohl das größte Problem sei.

# Analyze the slow query log and produce a ranked digest report
pt-query-digest /var/log/mysql/slow-query.log > digest-report.txt

# Excerpt of typical output, sorted by total execution time
# Rank Query ID           Response time  Calls R/Call V/M   Item
# ==== ================== ============== ===== ====== ===== =========
#    1 0x9F3A...           842.31 68.2%  12043  0.0699  0.02 SELECT orders
#    2 0x4B21...           201.55 16.3%     89  2.2646  0.51 SELECT products
#    3 0x7C08...            94.72  7.7%   5502  0.0172  0.01 UPDATE inventory

# Focus on a single query class by its ID for full detail
pt-query-digest --filter '$event->{fingerprint} =~ m/select orders/i' \
  /var/log/mysql/slow-query.log

5. mysqldumpslow als leichtgewichtige Alternative

Wo pt-query-digest nicht installiert werden kann oder eine schnellere, ohne externe Abhängigkeiten auskommende Lösung gebraucht wird, liefert das in jeder MySQL-Distribution mitgelieferte mysqldumpslow eine einfachere, aber funktional ähnliche Aggregation. Es normalisiert ebenfalls Literale zu Platzhaltern und gruppiert nach Query-Muster, bietet aber weniger Kennzahlen und eine deutlich rudimentärere Ausgabeformatierung als pt-query-digest.

Für schnelle Checks direkt auf dem Datenbankserver, ohne die Log-Datei erst herunterladen zu müssen, ist mysqldumpslow dennoch praktisch. Die Option -s t sortiert nach Gesamtzeit, -s c nach Anzahl der Ausführungen, und -t N begrenzt die Ausgabe auf die N relevantesten Einträge. Für tiefere Analysen mit Histogrammen, Prozentanteilen und Trendvergleichen zwischen mehreren Zeiträumen bleibt pt-query-digest jedoch die überlegene Wahl.

# Top 10 query patterns by total execution time
mysqldumpslow -s t -t 10 /var/log/mysql/slow-query.log

# Top 10 query patterns by number of occurrences
mysqldumpslow -s c -t 10 /var/log/mysql/slow-query.log

# Example output line (literals replaced with N and 'S')
# Count: 12043  Time=0.07s (842s)  Lock=0.00s (0s)  Rows=1.2 (14452)
#   SELECT * FROM orders WHERE customer_id = N AND status = 'S'

6. Muster erkennen: welche Query-Typen dominieren

Nach der Aggregation folgt die Musterklassifizierung. In der Praxis lassen sich langsame Anfragen meist in wiederkehrende Kategorien einteilen: fehlende oder ungünstige Indizes, die zu vollständigen Tabellenscans führen, ineffiziente JOINs ohne passende Indexunterstützung auf der Join-Spalte, N+1-Muster mit vielen strukturell identischen, aber sehr häufigen Anfragen, sowie große Sortier- oder Gruppierungsoperationen ohne unterstützenden Index, die MySQL zu temporären Tabellen und Filesort-Operationen zwingen.

Ein Blick auf die Spalte Rows_examined im Verhältnis zu Rows_sent im Slow Query Log verrät dabei viel über die Art des Problems. Untersucht eine Anfrage hunderttausende Zeilen, um nur wenige zurückzugeben, deutet das stark auf einen fehlenden oder falsch gewählten Index hin. Ist die Anzahl untersuchter und zurückgegebener Zeilen dagegen ähnlich hoch, liegt das Problem eher an der schieren Datenmenge oder einer grundsätzlich zu breiten Anfrage, die möglicherweise durch Paginierung oder gezieltere Filter eingegrenzt werden sollte.

7. Von Log-Eintrag über EXPLAIN zum Fix

Sobald eine priorisierte Query-Klasse aus dem Slow Query Log identifiziert ist, folgt die Detailanalyse mit EXPLAIN beziehungsweise EXPLAIN ANALYZE in MySQL 8.0. Diese Werkzeuge zeigen den tatsächlich gewählten Ausführungsplan, welche Indizes der Optimizer in Betracht gezogen und tatsächlich verwendet hat, und wie viele Zeilen pro Schritt geschätzt beziehungsweise tatsächlich verarbeitet wurden. Ein Ausführungsplan mit type: ALL signalisiert einen vollständigen Tabellenscan und ist bei großen Tabellen fast immer ein starkes Signal für einen fehlenden Index.

Nach dem Anlegen eines passenden Index oder der Umformulierung der Anfrage sollte der Fix nicht nur in der Theorie, sondern erneut im Slow Query Log verifiziert werden, idealerweise durch einen erneuten Digest-Lauf nach einigen Tagen Produktivbetrieb. Nur so lässt sich zuverlässig belegen, dass die betroffene Query-Klasse tatsächlich aus der Liste der Top-Verursacher verschwunden ist, statt sich auf eine einzelne, isolierte Testmessung zu verlassen.

8. Rotation und Langzeit-Monitoring

Ein aktiver Slow Query Log ohne Rotation wächst unbegrenzt und kann bei stark frequentierten Systemen innerhalb weniger Tage mehrere Gigabyte erreichen. logrotate unter Linux ist die etablierte Lösung, kombiniert mit einem postrotate-Skript, das MySQL per FLUSH LOGS anweist, die Log-Datei neu zu öffnen, statt weiterhin in die bereits rotierte, umbenannte Datei zu schreiben. Ohne diesen Schritt schreibt der MySQL-Prozess unter Umständen weiterhin in einen Dateideskriptor, der auf die alte, rotierte Datei zeigt, was den Rotationseffekt zunichtemacht.

Für Langzeit-Trends lohnt sich die tägliche oder wöchentliche automatisierte Ausführung von pt-query-digest mit Speicherung der Ergebnisse in einer eigenen Tabelle, kombiniert mit Percona Monitoring and Management oder einem vergleichbaren Dashboard. So lässt sich über Wochen beobachten, ob eine bestimmte Query-Klasse nach einem Deployment plötzlich häufiger oder langsamer wird, ein Muster, das bei einer isolierten Momentaufnahme des Slow Query Logs leicht übersehen wird.

9. Priorisierung: Impact als Frequenz mal Dauer

Die zentrale Formel für eine belastbare Priorisierung aus dem Slow Query Log lautet: Impact gleich Ausführungshäufigkeit multipliziert mit durchschnittlicher Dauer, exakt die Kennzahl, die pt-query-digest standardmäßig als Sortierkriterium verwendet. Eine Anfrage mit 50 Millisekunden Dauer, aber zehntausend Ausführungen pro Stunde, bindet in Summe mehr Datenbankressourcen als eine einzelne Fünf-Sekunden-Anfrage, die nur einmal am Tag läuft, selbst wenn Letztere im ersten Moment dramatischer wirkt.

Neben der reinen Zeitsumme lohnt sich ein zweiter Blick auf Anfragen mit hoher Varianz zwischen minimaler und maximaler Ausführungszeit, sichtbar in der V/M-Spalte von pt-query-digest. Große Schwankungen deuten oft auf Lock-Wartezeiten, fehlenden Buffer-Pool-Speicher für bestimmte Datenmengen, oder Plan-Instabilität durch veraltete Tabellenstatistiken hin, Probleme, die sich nicht allein durch einen zusätzlichen Index lösen lassen, sondern eine tiefere Ursachenanalyse erfordern.

10. Zusammenfassung

Der Slow Query Log allein liefert keinen Mehrwert, solange er nicht systematisch ausgewertet wird. Die richtige Konfiguration beginnt mit einer sinnvollen long_query_time, angepasst an die tatsächlichen Latenzanforderungen der Anwendung statt am wenig hilfreichen Standardwert von 10 Sekunden, ergänzt durch log_queries_not_using_indexes für frühzeitige Warnungen. pt-query-digest aggregiert die Rohdaten zu priorisierbaren Query-Klassen, sortiert nach tatsächlichem Gesamteinfluss statt nach subjektivem Eindruck einzelner langsamer Anfragen.

Der Workflow von Log-Eintrag über EXPLAIN zum konkreten Fix, gefolgt von einer erneuten Verifikation im Slow Query Log nach dem Deployment, schließt den Kreis. Rotation und wiederkehrende Digest-Läufe verwandeln eine einmalige Momentaufnahme in kontinuierliches Performance-Monitoring, das neue Regressionen erkennt, bevor sie zum echten Produktionsproblem werden.

11. FAQ: Slow Query Log systematisch auswerten