Eile mit Weile: mysqldumpslow

Mittlerweile gibt es unterschiedliche Werkzeuge, um Performance-Probleme in MySQL aufzudecken. Nicht immer stehen diese jedoch ad hoc bei unseren Analysen auf Kundensystemen zur Verfügung. Zwar ist beispielsweise das „performance_schema" in den aktuellen MySQL-Version per default aktiviert, jedoch nutzen viele unser Kunden noch ältere MySQL-Versionen, wo dies nicht der Fall war. Zum Glück gibt es aber aber auch etablierte, althergebrachte Werkzeuge, die unmittelbar genutzt werden können und immer noch gute Dienste leisten.

Mach mal langsam:  Slow Query Log

Die Aufgabe des Slow Query Log (slow_query_log) besteht darin, langlaufende SQL-Statements zu protokollieren. Über den Parameter „long_query_time" kann dabei definiert werden, ab wie vielen Sekunden eine Query als „langsam" interpretiert wird. Zusätzlich können auch noch einige weitere Einstellungen vorgenommen werden. So kann beispielsweise dafür gesorgt werden, dass SQL-Statements generell protokolliert werden, wenn diese keinen Index benutzen („log_queries_not_using_indexes").

Eine vollständige Liste von weiteren Konfigurationsmöglichkeiten des Slow Query Logs finden Sie hier: https://dev.mysql.com/doc/refman/8.0/en/slow-query-log.html

Immer schön flexibel bleiben!

Besonders schön ist die Tatsache, dass alle relevanten Parameter des Slow Query Logs online (also ohne Neustart des Servers) zu konfigurieren sind. Dies erlaubt eine unverzügliche Aktvierung der Parameter, um mit der Sammlung von Statements direkt beginnen zu können.

mysql> set global slow_query_log=on;
Query OK, 0 rows affected (0.00 sec)
mysql> set global long_query_time=0.001;
Query OK, 0 rows affected (0.00 sec) 

Ab diesem Moment werden Statements dokumentiert, die länger laufen als 0.001 Sekunden. Dieser Schwellwert ist natürlich extrem niedrig und dient hier nur zur Veranschaulichung. In der Praxis muss diese Metrik mit den erwarteten Antwortzeiten der Applikation abgestimmt werden. Per default landen diese in einem Logfile im Datenbankverzeichnis („ac45b902f5d7" ist in diesem Fall der Hostname in unserem MySQL-Docker-Container).

bash-4.2# ls -la /var/lib/mysql/ac45b902f5d7-slow.log
-rw-r----- 1 mysql mysql 179 Aug 21 13:54 /var/lib/mysql/ac45b902f5d7-slow.log 

Dies kann natürlich anders konfiguriert werden. Im Prinzip können die Informationen auch in eine Systemtabelle „mysql.slow_log" geschrieben werden. Dazu muss der Parameter „log_output" auf „table" gesetzt werden. In unserem Fall wäre dies jedoch kontraproduktiv, da unser Auswertungswerkzeug im nächsten Schritt ausschließlich mit Log-Dateien arbeitet.

Keinem zur Last fallen.

Nachdem wir das Slow Query Log mit sehr niedrigen Schwellwerten konfiguriert haben, sorgen wir nun dafür, dass wir ein paar Daten (Langläufer) generieren. Wir nutzen dafür die MySQL-Beispiel-Datenbank „sakila". Sie kann über die folgende URL bezogen werden:

https://dev.mysql.com/doc/sakila/en/sakila-installation.html

Zusätzlich nutzen wir einige Beispiel-Queries, die von Joel Sotelo (joelsotelods) über GitHub bereit gestellt wurden.

https://github.com/joelsotelods/sakila-db-queries

Die entsprechenden Statements haben wir mehrere Minuten in einer Endlosschleife (Shell) gegen die MySQL-Datenbank ausgeführt, um ein paar MB an Daten im Slow Query Log zu erzeugen.

Diese Daten sollen nun ausgewertet werden.

Wer suchet, der findet…

MySQL liefert mit dem Werkzeug „mysqldumpslow" ein sehr geeignetes Werkzeug, um die Daten aus dem Slow Query Log auszuwerten. Generell aggregiert „mysqldumpslow" gleichartige Statements und gibt das Ergebnis sortiert zurück. Zusätzlich lassen sich bei der Analyse einige Filter definieren (Größe der Ergebnismenge oder bestimmte Pattern im SQL-Statement; z.b. Tabellennamen o.ä.). Bei der Aggregation von Statements werden Strings und numerische Werte „standardisiert".

So werden die folgenden drei SELECTs beispielsweise in der Auswertung zusammengefasst (Ausgaben vereinfacht):

SELECT first_name FROM actor WHERE first_name like '%JOHNNY%';
SELECT first_name FROM actor WHERE first_name like '%PAUL%';
SELECT first_name FROM actor WHERE first_name like '%HEATHER%';

bash> mysqldumpslow  names.log
Reading mysql slow query log from names.log
Count: 3  Time=0.01s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  SELECT first_name FROM actor WHERE first_name like 'S' 

• Laufzeit der Statements
• Sperrzeit (Locks) der Statements
• gesendete Ergebnismengen (Anzahl von Datensätzen) der Statements
• Häufigkeit der Ausführung von Statements

# Ausgaben der Statements gekürzt.
bash> mysqldumpslow -t 3 -s at ac45b902f5d7-slow.log 

Reading mysql slow query log from ac45b902f5d7-slow.log

Count: 1500  Time=12297829382.49s (18446744073740s)  Lock=0.00s (0s)  Rows=958.0 (1437000), root[root]@localhost
  select A.film_id, A.title, B.*
   from film A 
    join ( select inv.film_id, count(ren.rental_id) times_rented
  …

Count: 1504  Time=12265122389.45s (18446744073726s)  Lock=0.00s (0s)  Rows=997.0 (1499488), root[root]@localhost
  select flm.title, count(*) number_of_actors
…

Count: 10  Time=3.14s (31s)  Lock=0.00s (0s)  Rows=160.0 (1600), root[root]@localhost
  select first_name, last_name
… 

Im oben stehenden Beispiel wurden die Ergebnisse des Logs nach der durchschnittlichen Laufzeit der SQLs sortiert (-a at; Average Time) und bei der Ergebnismenge auf die TOP 3 Queries begrenzt (-t 3).

Eine Übersicht über das Tool „mysqldumpslow" und alle möglichen Parameter finden Sie hier:

https://dev.mysql.com/doc/refman/5.7/en/mysqldumpslow.html

Fazit: Oldie but Goldie

Natürlich gibt es heute schönere Wege, um problematische Statements in einer MySQL-Datenbank zu finden (z.B: das „performance_schema"). Trotzdem erfüllt das Slow Query Log immer noch für viele Kunden seinen Sinn (gerade bei älteren Installationen). Es kann unkompliziert (online) aktiviert und direkt ausgewertet werden (auch für spezifische Zeiträume; z.B. während einer bestimmten Verarbeitung der Applikation). Darüber hinaus können alle Einstellungen wahlweise serverweit (global) oder auch nur für die eigene Session (local) konfiguriert werden.