23. December 2006, 20:39, by Silvan Mühlemann

Optimierung von MySQL-Abfragen: Der Slow-Query-Log

Delfin Den Feedbacks von meinem letzten Beitrag nach zu schliessen, stösst das Thema Query-Optimierung auf Interesse. Ich werde deshalb in nächster Zeit mehrere Artikel zu diesem Thema schreiben. Schritt 1: Die langsamen Queries identifizieren.

Unser erste Blick geht jeweils in den Slow-Query-Log. Braucht eine Abfrage mehr als 10 Sekunden, so wird sie in hostname.slow aufgelistet. Dieses Logging wird im my.cnf mit dem Keyword log-slow-queries aktiviert.

Hier ein Auszug aus diesem Log:

# …
# Time: 060608 3:16:57
# User@Host: tilllate[tilllate] @ localhost []
# Query_time: 86 Lock_time: 0 Rows_sent: 10 Rows_examined: 18143261
SELECT rs.site_id,count(distinct fotos.eventid) as c from fotos,site_regionen rs
WHERE fotos.rid=rs.regionid
GROUP BY rs.site_id;

# Time: 060608 3:18:18
# User@Host: tilllate[tilllate] @ localhost []
# Query_time: 81 Lock_time: 0 Rows_sent: 10 Rows_examined: 22507487
SELECT rs.site_id,count(distinct p.lid) as c
FROM fotos f
inner join events p on f.eventid=p.eventid
inner join site_regionen rs on rs.regionid=p.rid_cache
# …

Interessant nebst der eigentlichen Query ist die zweite Zeile nach dem Timestamp. Hier liest man folgendes raus:

Query_time: Laufzeit der Query in Sekunden
Lock_time: Ist eine Tabelle gelockt (z.B. wegen einem gerade laufenden UPDATE oder INSERT), muss die Query warten, bis diese Operationen abgeschlossen sind. In Lock_time steht diese Wartezeit. Hohe Werte hier deuten auf einen zu hohen Anteil den Datenbestand ändernde Queries. Dies ist besonders bei MyISAM-Tabellen, welche jeweils gleich die ganze Tabelle für SELECTs sperren anzutreffen.
Rows_sent: Anzahl dem Client zurückgegebene Zeilen.
Rows_examined: Anzahl Zeilen, welche sequentiell (und aufwändig) durchgescannt werden mussten, da die Indizes nicht optimal eingesetzt werden konnten. Diese Zahl muss niedrig sein. Werte über 1000 sind schlecht.

Im Beispiel oben liest man heraus, dass die beiden aufgeführten Queries extrem schlecht sind. Extrem Schlecht. 22 Mio. Zeilen müssen von der Disk gelesen und in eine temporäre Tabelle geschrieben werden. Diese temporäre Tabelle wird dann sequentiell durchlaufen und für jede Zeile wird geprüft, ob die Bedingungen zutreffen. Es wundert mich, dass die Query nur 81 Sekunden dauert.

Nun, diese Query kennen wir. Eine kleine Hexe. Lässt sich nicht optimieren. Da sie so langsam ist, hat sie ihren Auftritt mitten in der Nacht, wenn niemand auf tilllate.com surft, 3AM.

Hitparade der lahmsten Queries

Wo beginnt man nun mit der Optimierung? Am besten bei den Queries, welche häufig auftreten und besonders langsam sind. Jene, welche nur einmal auftreten können wir vorerst mal vergessen.

Bei uns im Slow-Query-Log kommen pro Tag schnell 10’000 Zeilen zusammen. Eine manuelle Auswertung ist da unmöglich. Die Lösung liefern die Jungs von MySQL AB gleich mit: mysqldumpslow. Hinter diesem bescheidenen Namen steckt ein Tool, welches aus dem Slow-Query-Log eine Hitparade der teuersten Queries erstellt.

Wir verwenden es meist wie folgt:

pig mysql # mysqldumpslow pig-slow.log1 -t 10 -s t

Reading mysql slow query log from pig-slow.log1
Count: 1004  Time=4277874.00s (-1s)  Lock=3.76s (3773s)
  Rows=1.1 (1073), tilllate[tilllate]@localhost
  select * from member_options WHERE uid='S'

Count: 4302  Time=99.71s (428938s)  Lock=28.78s (123815s)
  Rows=1.0 (4292), tilllate[tilllate]@localhost
  SELECT ts FROM login_log WHERE uid='S'
  AND result IN (N,N)
  ORDER BY ts DESC LIMIT N

Count: 1343  Time=60.51s (81267s)  Lock=22.55s (30286s)
  Rows=54.8 (73577), tilllate[tilllate]@localhost
  SELECT fotos.foto_id FROM (its_me,fotos,events 

  [...]

Der verwendete Befehl liefert die Top-10 Queries aus (-t 10), sortiert nach der summierten Ausführungszeit aller Queries (-s t, ‘sort by total time’).

Was fällt uns auf? Zuerst mal die erste Query, wo die Ausführungszeit “-1s” sein soll. Schön wär’s. Ein Bug. Ignorieren wir.

Die zweite Query ist schon interessanter. Im 4302 mal wurde diese Query ausgeführt. Und im Schnitt dauerte sie 99 Sekunden. Uebel. Da gibt’s Verbesserungspotential.

Was bedeuten die “S” und “N” im Querytext? Das sind Platzhalter für Konstanten in der WHERE-Clause. Z.B. in “SELECT * FROM EVENTS eventid=234” die “234″. Bevor die Laufzeiten von identischen Queries zusammengezählt werden können, welchen Konstante so ersetzt. Diese Ersetzung wird gemacht, da ja auch “SELECT * FROM EVENTS eventid=456” ja die gleiche Query ist (und wohl an der gleichen Stelle im Programmcode zu finden ist), einfach mit anderen Konstanten. Durch die Ersetzung der Konstanten kriegt man “SELECT * FROM EVENTS eventid=S“.

Wir würden nun diese lahmen Queries eine um die andere durchgehen und schauen, was wir tun können, damit diese weniger Laufzeit haben. Dies kann eine Optimierung der Query sein über bessere Index-Verwendung, eine Vermeidung der Query oder eine Reduktion der Häufigkeit über Caching. Diese Schritte möchte ich aber in einem späteren Artikel dieses Blogs anschauen.

techblog.tilllate.com

tilllate.com photos

Pages

Search:

Archives:

Meta:

Optimierung von MySQL-Abfragen: Der Slow-Query-Log

Hitparade der lahmsten Queries

No Comments »

Leave a comment