Die teuersten Abfragen finden, nicht die langsamsten
Eine Abfrage mit 80 Millisekunden, die zwanzigtausendmal am Tag läuft, kostet mehr Rechenzeit als der eine Bericht, über den sich alle beschweren.
KI-generiertDieses Bild wurde mit KI erzeugt · Yves Hoppe / KI / cmt
Die Voreinstellung sorgt dafür, dass das Log nichts Nützliches enthält
long_query_time steht ab Werk auf zehn Sekunden. Eine Webanwendung, deren Abfragen zwischen zwanzig und dreihundert Millisekunden brauchen, erzeugt damit keinen einzigen Protokolleintrag, auch wenn der Server durchgehend bei hoher Auslastung läuft. Wer daraufhin schließt, es gebe keine langsamen Abfragen, sucht das Problem danach an der falschen Stelle, meist beim Arbeitsspeicher oder bei der Plattengeschwindigkeit.
Die zweite Falle ist die Sortierung. Wird die Schwelle gesenkt, füllt sich das Log schnell mit Zehntausenden Einträgen, und die naheliegende Reaktion ist, nach der längsten Einzellaufzeit zu sortieren. Ganz oben steht dann der nächtliche Bericht, der drei Minuten braucht und einmal täglich läuft. Ihn zu optimieren spart drei Minuten am Tag. Die Abfrage auf Platz vierhundert der Liste, achtzig Millisekunden bei zwanzigtausend Aufrufen, kostet knapp eine halbe Stunde Rechenzeit täglich.
Dazu kommt, dass eine hohe Laufzeit im Log nicht bedeuten muss, dass die Abfrage selbst teuer ist. Query_time enthält auch die Zeit, in der die Abfrage auf eine Zeilensperre gewartet hat, und diese Wartezeit taucht in Lock_time nicht auf, denn dort steht nur der Erwerb der anfänglichen Tabellen- und Metadatensperren. Wer eine solche Zeile für eine teure Abfrage hält, baut Indizes für einen Fall, der in Wahrheit nur blockiert wurde.
KI-generiertDieses Bild wurde mit KI erzeugt · Yves Hoppe / KI / cmt
Schritt für Schritt
- 1
Ein Zeitfenster mit echter Last festlegen
Ein Mitschnitt ist nur so gut wie die Last, die währenddessen läuft. Nimm dreißig bis sechzig Minuten zur Hauptzeit, nicht den ruhigen Vormittag und nicht das Wartungsfenster. Wenn dich eine wiederkehrende Beschwerde interessiert, etwa der Montagmorgen, dann leg das Fenster genau dorthin.
Geschafft, wenn: Der Mitschnitt deckt einen Zeitraum ab, in dem das gemeldete Problem tatsächlich auftritt.
- 2
Das Log einschalten und die Schwelle absenken
SET GLOBAL slow_query_log = ON und SET GLOBAL long_query_time = 0 schalten den Mitschnitt im laufenden Betrieb ein, ohne Neustart. Ergänz SET GLOBAL log_slow_admin_statements = ON, damit ALTER TABLE und ähnliche Anweisungen mit erfasst werden, und log_slow_extra, weil dann unter anderem die Zahl der auf Platte angelegten temporären Tabellen im Log steht. Für die Dateiausgabe ist log_output = FILE die richtige Wahl, denn die Zusatzfelder werden nur dorthin geschrieben.
Geschafft, wenn: Die Protokolldatei wächst sichtbar, und ein Blick hinein zeigt Einträge mit Query_time-Werten unter einer Sekunde.
- 3
Das Fenster wieder schließen
Nach dem Mitschnitt setzt du long_query_time zurück, üblicherweise auf einen Wert zwischen 0,5 und 2 Sekunden für den Dauerbetrieb, und lässt das Log dabei eingeschaltet. Eine dauerhaft auf null gesetzte Schwelle schreibt jede Abfrage auf die Platte und kostet auf einem stark belasteten Server messbar Leistung. Denk außerdem an die Dateigröße: Ohne Rotation läuft eine Partition schneller voll, als einem lieb ist.
Geschafft, wenn: Der Server läuft wieder mit der Dauereinstellung, die Datei ist gesichert und liegt zur Auswertung bereit.
- 4
Einträge zu Abfragemustern zusammenfassen
Einzelne Einträge zu lesen führt nirgendwohin, weil sich dieselbe Abfrage nur in den Parametern unterscheidet. pt-query-digest ersetzt Werte und Zeichenketten durch Platzhalter, gruppiert die Einträge danach und gibt je Muster Anzahl, Gesamtzeit, Mittelwert, das 95. Perzentil sowie Rows_examined und Rows_sent aus. Ist das Werkzeug nicht verfügbar, liefert das mitgelieferte mysqldumpslow eine gröbere, aber brauchbare Zusammenfassung.
Geschafft, wenn: Aus zehntausenden Zeilen sind einige Dutzend Muster mit Kennzahlen geworden.
- 5
Nach Gesamtlast sortieren und die ersten fünf herausschreiben
Sortier nach der Summe der Laufzeiten, nicht nach dem Maximum. In den meisten Auswertungen entfallen auf die ersten drei bis fünf Muster mehr als die Hälfte der gesamten Abfragezeit, und das ist die Liste, an der du arbeitest. Notier zu jedem Muster die Anzahl, denn sie entscheidet später, ob ein zusätzlicher Index seinen Schreibaufwand wert ist.
Geschafft, wenn: Es existiert eine kurze, nach Gesamtzeit geordnete Liste mit höchstens fünf Einträgen.
- 6
Gegenprobe im Performance Schema
SELECT DIGEST_TEXT, COUNT_STAR, SUM_TIMER_WAIT, SUM_ROWS_EXAMINED, SUM_ROWS_SENT, SUM_NO_INDEX_USED FROM performance_schema.events_statements_summary_by_digest ORDER BY SUM_TIMER_WAIT DESC LIMIT 10 liefert dieselbe Rangfolge aus einer unabhängigen Quelle. Die Werte gelten seit dem Serverstart oder seit dem letzten TRUNCATE auf diese Tabelle. Die sys-Sicht statement_analysis bereitet dasselbe lesbar auf.
Geschafft, wenn: Beide Quellen nennen im Wesentlichen dieselben Muster, oder die Abweichung ist erklärt.
- 7
Für jedes Muster einen echten Parametersatz besorgen
EXPLAIN braucht konkrete Werte, keine Platzhalter. Nimm aus dem Log eine tatsächlich vorgekommene Ausprägung des Musters, möglichst eine mit hoher Laufzeit, und lass darauf EXPLAIN ANALYZE laufen. Der Unterschied zwischen geschätzter und tatsächlicher Zeilenzahl in der Ausgabe ist der Punkt, an dem die eigentliche Arbeit beginnt.
Geschafft, wenn: Zu jedem der fünf Muster liegt ein Ausführungsplan mit gemessenen Zeilenzahlen vor.
Fünf Kennzahlen, die ein Abfragemuster beschreiben
- 01 Die Anzahl der Aufrufe sagt, ob sich eine Verbesserung überhaupt lohnt.
- 02 Die Gesamtlaufzeit ist die Reihenfolge, nach der du vorgehst.
- 03 Die Laufzeit im 95. Perzentil zeigt, wie stark die Ausreißer streuen.
- 04 Rows_examined gegen Rows_sent verrät fehlende oder unpassende Indizes.
- 05 Lock_time deckt nur Tabellensperren ab, Zeilensperren stecken unbemerkt in Query_time.
Danach kennst du die zehn Abfragen, die deinen Server tatsächlich beschäftigen
Das Vorgehen besteht aus vier Schritten, die aufeinander aufbauen: ein begrenztes Zeitfenster mit abgesenkter Schwelle, das Zusammenfassen der Einträge zu Mustern, die Sortierung nach Gesamtlast und erst danach die Einzelbetrachtung mit EXPLAIN.
Das Log im laufenden Betrieb einschalten
slow_query_log und long_query_time lassen sich zur Laufzeit setzen, ein Neustart ist nicht nötig. Damit kannst du ein Fenster von dreißig bis sechzig Minuten unter echter Last mitschneiden und danach wieder auf den alten Stand gehen.
Die Schwelle bewusst zu tief setzen
long_query_time akzeptiert Bruchteile von Sekunden bis in den Mikrosekundenbereich. Für ein kurzes Fenster ist 0 die richtige Wahl, weil dann jede Abfrage im Log landet und die Auswertung überhaupt erst repräsentativ wird.
Nach Mustern zusammenfassen, nicht nach Einträgen lesen
pt-query-digest ersetzt konkrete Werte durch Platzhalter und fasst dadurch tausende Einträge zu wenigen Abfragemustern zusammen. Das mitgelieferte mysqldumpslow kann dasselbe im Ansatz, wenn kein zusätzliches Werkzeug installiert werden darf.
Nach Gesamtlaufzeit sortieren
Anzahl mal durchschnittliche Laufzeit ist die Kennzahl, die zählt. Sie beantwortet die Frage, wie viel Rechenzeit du zurückbekommst, wenn dieses eine Muster halb so teuer wird.
Rows_examined gegen Rows_sent halten
Wenn eine Abfrage hunderttausend Zeilen liest, um zehn zurückzugeben, fehlt fast immer ein Index oder er passt nicht zur Sortierung. Dieses Verhältnis ist der zuverlässigste Hinweis darauf, welches Muster sich lohnt.
Das Performance Schema als zweite Quelle nutzen
events_statements_summary_by_digest sammelt dieselben Kennzahlen laufend und ohne Protokolldatei. Das ist der schnellste Einstieg, wenn du das Log gar nicht erst einschalten darfst.
KI-generiertDieses Bild wurde mit KI erzeugt · Yves Hoppe / KI / cmt
Was im Log steht und was nicht
Jeder Eintrag beginnt mit einem Kopf aus Zeitstempel, Benutzer und Verbindung, danach folgen Query_time, Lock_time, Rows_sent und Rows_examined und schließlich die Anweisung selbst. Wichtig ist, was Lock_time nicht enthält: Der Wert deckt nur den Erwerb der anfänglichen Tabellen- und Metadatensperren ab. Die Wartezeit auf eine InnoDB-Zeilensperre steckt dagegen in Query_time, während Lock_time nahe null bleibt. Eine hohe Query_time bei winziger Lock_time schließt eine Blockierung also gerade nicht aus, und ob eine wartete, beantwortet nicht das Log, sondern performance_schema.data_lock_waits beziehungsweise die Sicht sys.innodb_lock_waits im Moment des Wartens.
Mit log_slow_extra kommen Felder dazu, die viel Analysearbeit ersparen: Created_tmp_disk_tables zeigt, dass eine temporäre Tabelle auf der Platte angelegt wurde, Sort_merge_passes weist auf eine Sortierung hin, die nicht in den Speicher passte, die Read-Zähler zeigen, wie auf die Tabellen zugegriffen wurde. Diese Felder werden ausschließlich in die Datei geschrieben, nicht in die Tabellenausgabe.
Nicht im Log stehen drei Dinge, die man dort oft sucht. Abfragen, die noch laufen, erscheinen nie, weil der Eintrag erst am Ende geschrieben wird. Dafür ist SHOW PROCESSLIST oder performance_schema.events_statements_current zuständig. Abgewiesene Verbindungen erscheinen ebenfalls nicht, und Anweisungen von der Replikation nur, wenn log_slow_replica_statements gesetzt ist.
Die Schwelle entscheidet, was du überhaupt zu sehen bekommst
Zehn Sekunden als Voreinstellung stammen aus einer Zeit, in der eine Abfrage mit einer Sekunde als schnell galt. Für heutige Anwendungen ist der Wert so hoch, dass er die interessante Masse ausblendet. Für den Dauerbetrieb hat sich ein Wert zwischen einer halben und zwei Sekunden bewährt, weil das Log dann überschaubar bleibt und trotzdem Auffälligkeiten meldet.
Für die Analyse selbst ist null der richtige Wert, aber nur für ein begrenztes Fenster. Jede Abfrage erzeugt dann einen Schreibvorgang, was auf einem Server mit einigen tausend Abfragen je Sekunde spürbar wird. Zwei Einstellungen dämpfen das Volumen, ohne die Aussage zu verfälschen: min_examined_row_limit blendet Abfragen aus, die weniger als eine bestimmte Zahl Zeilen angeschaut haben, und log_throttle_queries_not_using_indexes begrenzt, wie viele Einträge ohne Indexnutzung je Minute geschrieben werden.
log_queries_not_using_indexes klingt verlockend, ist aber für sich genommen kein guter Filter. Eine kleine Nachschlagetabelle mit dreißig Zeilen wird zu Recht vollständig gelesen, taucht aber bei jedem Zugriff im Log auf. Ohne die Drosselung besteht das Log nach kurzer Zeit fast nur aus solchen Einträgen.
Warum das Zusammenfassen zu Mustern der eigentliche Schritt ist
Dieselbe Abfrage erscheint im Log hunderte Male mit unterschiedlichen Parametern. Für die Bewertung interessiert nicht der einzelne Aufruf, sondern das Muster dahinter. pt-query-digest aus der Percona Toolkit erledigt genau das: Es normalisiert die Anweisung, indem es Werte und Zeichenketten durch Platzhalter ersetzt, gruppiert danach und rechnet je Gruppe Anzahl, Summe, Mittelwert, das 95. Perzentil und die Zeilenverhältnisse aus.
Das 95. Perzentil ist dabei aussagekräftiger als der Mittelwert. Wenn ein Muster im Mittel 40 Millisekunden braucht, im 95. Perzentil aber 2 Sekunden, hängt die Laufzeit an den übergebenen Werten. Meist ist das ein Filter, der für manche Ausprägungen einen Index nutzt und für andere nicht, etwa weil eine seltene Kategorie sich völlig anders verteilt als die häufige.
Wenn kein zusätzliches Werkzeug installiert werden darf, kommt mysqldumpslow zum Zug, das dem Server beiliegt. Es fasst ebenfalls zusammen und kann nach Anzahl, Gesamtzeit oder durchschnittlicher Zeit sortieren. Die Auswertung ist gröber, für die Frage nach den fünf teuersten Mustern reicht sie aber.
Das Performance Schema, wenn du gar kein Log anfassen darfst
Auf einem System, an dem du keine Protokollierung einschalten darfst, liefert das Performance Schema dieselbe Auswertung, ohne dass etwas geschrieben wird. events_statements_summary_by_digest führt je normalisierter Anweisung unter anderem COUNT_STAR für die Aufrufe, SUM_TIMER_WAIT für die Gesamtzeit in Pikosekunden, SUM_ROWS_EXAMINED und SUM_ROWS_SENT sowie SUM_NO_INDEX_USED und SUM_CREATED_TMP_DISK_TABLES.
Zwei Einschränkungen gehören dazu. Die Werte gelten seit dem Serverstart, nicht für einen Zeitraum. Willst du ein Fenster messen, setzt du die Tabelle mit TRUNCATE TABLE performance_schema.events_statements_summary_by_digest zurück, wartest die gewünschte Zeit ab und liest dann. Und die Zahl der geführten Muster ist begrenzt, alles darüber hinaus fällt in einen Sammeleintrag, erkennbar an einem leeren DIGEST_TEXT.
Bequemer wird der Zugriff über die sys-Sichten, die auf denselben Tabellen aufsetzen und die Zahlen in lesbare Einheiten umrechnen. statement_analysis zeigt die Muster nach Gesamtzeit, statements_with_full_table_scans die Muster ohne Indexnutzung, statements_with_temp_tables die mit temporären Tabellen auf der Platte. Für einen ersten Überblick sind das drei Abfragen, die kein Werkzeug und keine Änderung an der Konfiguration brauchen.
Dazu passende Kurse
Wer regelmäßig messen statt raten will, braucht die Werkzeuge einmal im Zusammenhang, und genau dafür gibt es die MySQL-Schulungen zu Analyse und Tuning .
Wie sicher bist du beim Thema wirklich?
Lesen fühlt sich schnell nach Können an. Ein kurzer Test zeigt dir, was davon schon sitzt und wo sich ein Kurs lohnt. Kostenlos, ohne Anmeldung, mit einer Erklärung zu jeder Antwort.
Super Schulung, in der der Trainer auch auf eigene Fragestellungen eingegangen ist.
Super Grundlagenschulung mit allen wichtigen Punkten und hilfreichen Tipps!
Schön, sich 5 Tage ungestört mit Postgres beschäftigen zu können.
Häufige Fragen
Kostet ein eingeschaltetes Slow Query Log Leistung?
Warum steht eine Abfrage im Log, die eigentlich schnell ist?
Soll ich in die Datei oder in eine Tabelle protokollieren?
Wie finde ich Abfragen, die gerade jetzt hängen?
Deine Ansprechpartner
Du bist dir nicht sicher, welcher Kurs oder welches Level zu dir passt? Wir beraten dich persönlich und kostenlos.
Yves Hoppe
Weiterbildung & Beratung
Hilft dir, aus dem Datenbanken-Programm den passenden Kurs für deinen Stand zu finden.
Norbert Jansen
Beratung & Inhouse
Plant mit dir Inhouse-Trainings, die auf eure Abläufe und euren Datenbestand zugeschnitten sind.
Von der Vermutung zur gemessenen Rangfolge
Wie ein Mitschnitt aufgesetzt, ausgewertet und in konkrete Maßnahmen übersetzt wird, gehst du bei cmt an einem echten Datenbestand durch, bis die ersten fünf Muster benannt sind.