Slow Query Log systematisch auswerten

Warum das Slow Query Log unverzichtbar ist

Jede Produktionsdatenbank enthält früher oder später Abfragen, die unverhältnismäßig viel Zeit beanspruchen. Ohne geeignete Werkzeuge bleibt die Ursache im Verborgenen — die Anwendung wird langsamer, Nutzer beschweren sich, aber niemand weiß wo genau das Problem liegt. Das Slow Query Log ist Mysqls eingebauter Mechanismus, um genau solche Abfragen automatisch zu protokollieren. Wer es konsequent einsetzt, erhält einen kontinuierlichen Einblick in den Performance-Zustand seiner Datenbank — ohne auf externe Monitoring-Systeme angewiesen zu sein.

Dieser Artikel zeigt den vollständigen Workflow: Aktivierung in MySQL 8 mit der neuen Option log_slow_extra, das Verständnis der wichtigsten Logfelder, die Analyse mit mysqldumpslow und pt-query-digest sowie die abschließende Optimierung per EXPLAIN. Außerdem wird die Alternative über performance_schema.events_statements_summary_by_digest als ergänzendes Werkzeug vorgestellt.

1. Slow Query Log aktivieren in MySQL 8

In MySQL 8 kann das Slow Query Log entweder dauerhaft über die Konfigurationsdatei oder temporär per SQL-Befehl aktiviert werden. Letzteres erlaubt das Einschalten ohne Server-Neustart — ideal für Produktionsumgebungen, wo ein Neustart nicht einfach möglich ist.

Die Option log_slow_extra=ON ist eine Neuerung in MySQL 8 und schreibt deutlich mehr Diagnose-Informationen in jeden Log-Eintrag: CPU-Zeit aufgeteilt in User und System, Bytes_sent an den Client sowie Thread_id für die Korrelation mit SHOW PROCESSLIST.

Konfiguration über my.cnf

# /etc/mysql/my.cnf oder /etc/my.cnf

[mysqld]
# Enable the slow query log
slow_query_log          = ON
slow_query_log_file     = /var/log/mysql/slow.log

# Log queries taking longer than 1 second
long_query_time         = 1

# MySQL 8 only: log extra fields (CPU, Thread_id, Bytes_sent, I/O counters)
log_slow_extra          = ON

# Also log queries not using indexes (optional, but valuable)
log_queries_not_using_indexes = ON

# Prevent log flooding from log_queries_not_using_indexes
log_throttle_queries_not_using_indexes = 10
    

Aktivierung ohne Neustart per SQL

-- Enable slow query log at runtime (no restart required)
SET GLOBAL slow_query_log         = 'ON';
SET GLOBAL long_query_time        = 1;
SET GLOBAL slow_query_log_file    = '/var/log/mysql/slow.log';
SET GLOBAL log_slow_extra         = ON;  -- MySQL 8.0+ only

-- Verify current settings
SHOW VARIABLES LIKE 'slow_query_log%';
SHOW VARIABLES LIKE 'long_query_time';
SHOW VARIABLES LIKE 'log_slow_extra';
    

Der Wert long_query_time = 1 ist ein guter Ausgangspunkt. Auf hochperformanten Systemen mit SSD-Speicher und ausreichend RAM kann 0,5 oder sogar 0,1 Sekunden sinnvoll sein. Das Log sollte mindestens 24 Stunden unter normaler Produktionslast laufen, bevor man mit der Analyse beginnt — nur so erhält man ein repräsentatives Bild des tatsächlichen Query-Traffics.

2. Logfelder im Slow Query Log verstehen

Jeder Eintrag im Slow Query Log enthält mehrere Metriken-Zeilen, gefolgt von einem SET timestamp und der eigentlichen SQL-Anweisung. In MySQL 8 mit aktivem log_slow_extra sind diese Informationen besonders umfangreich und liefern ein vollständiges Bild der Ressourcennutzung.

# Time: 2025-02-12T14:32:17.123456Z
# User@Host: shop_user[shop_user] @ localhost []  Id: 4821
# Query_time: 4.238710  Lock_time: 0.000312  Rows_sent: 25  Rows_examined: 847293
# Thread_id: 4821  Errno: 0  Killed: 0  Bytes_received: 0  Bytes_sent: 3182
# Read_first: 0  Read_last: 0  Read_key: 25  Read_next: 847293  Read_rnd: 0
# Read_rnd_next: 0  Sort_merge_passes: 0  Sort_range_count: 0
# Sort_rows: 0  Sort_scan_count: 0  Created_tmp_disk_tables: 1
# Created_tmp_tables: 1  Start: 2025-02-12T14:32:13.000000Z
# End: 2025-02-12T14:32:17.000000Z
SET timestamp=1739368337;
SELECT p.entity_id, p.sku, p.name, SUM(oi.qty_ordered) AS total_sold
FROM catalog_product_entity p
JOIN sales_order_item oi ON oi.product_id = p.entity_id
WHERE p.status = 1 AND oi.created_at >= '2024-01-01'
GROUP BY p.entity_id
ORDER BY total_sold DESC
LIMIT 25;
    

Die wichtigsten Felder im Überblick:

• Query_time: Gesamtlaufzeit der Abfrage in Sekunden — der primäre Indikator
• Lock_time: Wartezeit auf Tabellen- oder Row-Level-Locks; hohe Werte deuten auf Lock-Konflikte hin
• Rows_sent: Anzahl der an den Client zurückgesendeten Zeilen
• Rows_examined: Anzahl der intern von der Storage Engine gelesenen Zeilen — Schlüsselmetrik
• Thread_id: MySQL-Thread-ID, verknüpfbar mit SHOW PROCESSLIST zur Echtzeit-Diagnose
• Created_tmp_disk_tables: Zahl der temporären Tabellen auf der Festplatte — Wert > 0 ist ein Warnsignal
• Read_next: Zahl der sequenziellen Lesevorgänge — hoher Wert ohne Index-Nutzung erkennbar

3. Das Rows_examined/Rows_sent-Verhältnis als Schlüsselindikator

Das Verhältnis von Rows_examined zu Rows_sent ist einer der aussagekräftigsten Indikatoren im Slow Query Log. Es zeigt, wie effizient MySQL Zeilen finden konnte, ohne dabei auf den absoluten Zeitwert allein angewiesen zu sein.

• Verhältnis 1:1 bis 10:1 — Ideal. MySQL findet die gesuchten Zeilen gezielt per Index.
• Verhältnis 100:1 bis 1.000:1 — Moderat. Hängt vom Anwendungsfall ab; bei aggregierten Reports oft unvermeidbar.
• Verhältnis 10.000:1 oder höher — Kritisch. Fast immer ein fehlender oder nicht genutzter Index. Full Table Scan sehr wahrscheinlich.

Im Beispiel oben: Rows_examined: 847.293, Rows_sent: 25 — das entspricht einem Verhältnis von 33.892:1. Die Abfrage scannt nahezu die gesamte Tabelle, um 25 Ergebnisse zu liefern. Ein zusammengesetzter Index auf (product_id, created_at) in der Tabelle sales_order_item würde hier die Rows_examined drastisch reduzieren.

-- Diagnose: Check what indexes exist on the table
SHOW INDEX FROM sales_order_item;

-- Add a composite index to fix the high rows_examined ratio
ALTER TABLE sales_order_item
    ADD INDEX idx_product_created (product_id, created_at);

-- Verify with EXPLAIN before and after
EXPLAIN SELECT p.entity_id, SUM(oi.qty_ordered) AS total_sold
FROM catalog_product_entity p
JOIN sales_order_item oi ON oi.product_id = p.entity_id
WHERE p.status = 1 AND oi.created_at >= '2024-01-01'
GROUP BY p.entity_id
ORDER BY total_sold DESC
LIMIT 25;
    

4. mysqldumpslow – schnelle Erstanalyse

mysqldumpslow ist ein Perl-Script, das MySQL mitliefert. Es liest das Slow Query Log, normalisiert Abfragen (ersetzt Literalwerte durch Platzhalter) und gruppiert identische Abfragemuster. So erkennt man in Sekunden, welche Abfragetypen am meisten Datenbankzeit kosten.

# Sort by total query time (-s t), show top 20 (-t 20)
mysqldumpslow -s t -t 20 /var/log/mysql/slow.log

# Sort by average query time (finds sporadic but expensive queries)
mysqldumpslow -s at -t 10 /var/log/mysql/slow.log

# Sort by number of occurrences (high-frequency patterns)
mysqldumpslow -s c -t 20 /var/log/mysql/slow.log

# Filter by specific database user
mysqldumpslow -s t -t 10 -u shop_user /var/log/mysql/slow.log

# Combined: top 10 by total time, show only SELECT statements
mysqldumpslow -s t -t 10 /var/log/mysql/slow.log | grep -A5 "SELECT"
    

Eine typische Ausgabe sieht so aus:

Count: 847  Time=4.24s (3590s)  Lock=0.00s (0s)  Rows=25.0 (21175),
shop_user[shop_user]@localhost

SELECT p.entity_id, p.sku, p.name, SUM(oi.qty_ordered) AS total_sold
FROM catalog_product_entity p
JOIN sales_order_item oi ON oi.product_id = p.entity_id
WHERE p.status = N AND oi.created_at >= 'S'
GROUP BY p.entity_id
ORDER BY total_sold DESC
LIMIT N;
    

Die Zeile Count: 847 Time=4.24s (3590s) zeigt: Diese Abfrage wurde 847-mal ausgeführt und hat insgesamt 3590 Sekunden Datenbankzeit verbraucht — fast eine Stunde reine CPU-Zeit für eine einzige Abfragevariante. Literalwerte werden durch N (Zahlen) und S (Strings) ersetzt, damit strukturell identische Abfragen mit unterschiedlichen Parametern zusammengefasst werden.

5. pt-query-digest – tiefe Analyse mit dem Percona Toolkit

pt-query-digest aus dem Percona Toolkit ist das professionelle Werkzeug für ernsthafte Slow-Query-Analysen. Es bietet Query-Fingerprinting, statistische Laufzeitverteilungen und einen strukturierten Bericht mit Prozentanteilen an der Gesamtlast. Für Produktionssysteme ist es mysqldumpslow in jeder Hinsicht überlegen.

# Install Percona Toolkit (Debian/Ubuntu)
apt-get install percona-toolkit

# Basic analysis: group and rank queries by total execution time
pt-query-digest /var/log/mysql/slow.log

# Limit output to the top 5 most expensive query fingerprints
pt-query-digest --limit 5 /var/log/mysql/slow.log

# Filter: only analyze queries running longer than 2 seconds
pt-query-digest --filter '$event->{Query_time} > 2' /var/log/mysql/slow.log

# Output the report to a file for later review
pt-query-digest /var/log/mysql/slow.log > /tmp/digest_report_$(date +%Y%m%d).txt

# Show only SELECT queries (ignore INSERT/UPDATE overhead)
pt-query-digest --filter '$event->{arg} =~ m/^SELECT/i' \
    /var/log/mysql/slow.log

# Analyze live MySQL traffic via tcpdump (no slow log needed)
tcpdump -s 65535 -x -nn -q -tttt -i any -c 2000 port 3306 \
    > /tmp/mysql_capture.txt
pt-query-digest --type tcpdump /tmp/mysql_capture.txt
    

Der pt-query-digest-Bericht gliedert sich in drei Teile: globale Statistiken über den Analyse-Zeitraum, eine nach Gesamtlast sortierte Rangliste aller Abfragemuster sowie detaillierte Profile pro Pattern mit Responsezeit-Histogramm, Perzentilen (p50, p95, p99) und zugehöriger Beispiel-Query. Besonders wertvoll ist die Prozentspalte, die zeigt, welcher Anteil der gesamten Datenbankzeit auf jedes Pattern entfällt.

6. Log-Rotation und die Alternative log_output=TABLE

Das Slow Query Log wächst auf stark frequentierten Systemen schnell auf mehrere Gigabyte. Ohne Rotation belegt es erheblichen Festplattenplatz und wird für Analyse-Tools unhandlich. Logrotate ist die empfohlene Lösung auf Linux-Systemen.

# Logrotate configuration: /etc/logrotate.d/mysql-slow
/var/log/mysql/slow.log {
    daily
    rotate 7
    missingok
    compress
    delaycompress
    notifempty
    postrotate
        # Instruct MySQL to reopen the log file after rotation
        mysqladmin -u root -p flush-logs slow 2>/dev/null || true
    endscript
}

-- Alternatively, flush the slow log directly via SQL
FLUSH SLOW LOGS;
    

Alternative: Slow Log in Datenbanktabelle schreiben

-- Write slow query log entries to mysql.slow_log table
SET GLOBAL log_output    = 'TABLE';
SET GLOBAL slow_query_log = 'ON';
SET GLOBAL long_query_time = 1;

-- Query the log using standard SQL
SELECT
    start_time,
    ROUND(TIME_TO_SEC(query_time), 3)  AS query_seconds,
    ROUND(TIME_TO_SEC(lock_time), 4)   AS lock_seconds,
    rows_sent,
    rows_examined,
    db,
    CONVERT(sql_text USING utf8mb4)    AS sql_text
FROM mysql.slow_log
WHERE query_time > '00:00:02'
ORDER BY query_time DESC
LIMIT 20;

-- Clear accumulated log entries
TRUNCATE mysql.slow_log;
    

Der Tabellenmodus ist praktisch für ad-hoc-Abfragen per SQL, erzeugt aber auf stark frequentierten Systemen zusätzlichen I/O durch das Schreiben in InnoDB-Tabellen. Für Produktionssysteme mit hohem Query-Traffic ist die Datei-Variante mit asynchronem Schreibvorgang performanter. Beide Modi können auch kombiniert werden: SET GLOBAL log_output = 'FILE,TABLE'.

7. Performance Schema als ergänzendes Diagnosewerkzeug

Die Tabelle performance_schema.events_statements_summary_by_digest bietet eine permanente, aggregierte Sicht auf alle ausgeführten Abfragen — unabhängig von ihrer Laufzeit und ohne Log-Datei. Sie ist in MySQL 8 standardmäßig aktiv und erfüllt eine andere Rolle als das Slow Query Log: Während letzteres nur langsame Abfragen protokolliert, erfasst das Performance Schema alle Queries inklusive hochfrequenter, schneller Abfragen, die in der Summe erhebliche Last erzeugen können.

-- Top 10 queries by total execution time
SELECT
    ROUND(SUM_TIMER_WAIT / 1e12, 2)        AS total_seconds,
    ROUND(AVG_TIMER_WAIT / 1e12, 4)        AS avg_seconds,
    COUNT_STAR                              AS executions,
    ROUND(SUM_ROWS_EXAMINED / COUNT_STAR)  AS avg_rows_examined,
    ROUND(SUM_ROWS_SENT / COUNT_STAR)      AS avg_rows_sent,
    SUM_CREATED_TMP_DISK_TABLES            AS tmp_disk_tables,
    LEFT(DIGEST_TEXT, 150)                 AS query_fingerprint
FROM performance_schema.events_statements_summary_by_digest
WHERE DIGEST_TEXT IS NOT NULL
ORDER BY SUM_TIMER_WAIT DESC
LIMIT 10;

-- Find queries with high rows_examined to rows_sent ratio
SELECT
    LEFT(DIGEST_TEXT, 100)                                          AS query,
    COUNT_STAR                                                      AS executions,
    SUM_ROWS_EXAMINED,
    SUM_ROWS_SENT,
    ROUND(SUM_ROWS_EXAMINED / NULLIF(SUM_ROWS_SENT, 0), 0)         AS examined_sent_ratio
FROM performance_schema.events_statements_summary_by_digest
WHERE SUM_ROWS_SENT > 0
    AND SUM_ROWS_EXAMINED / NULLIF(SUM_ROWS_SENT, 0) > 1000
ORDER BY examined_sent_ratio DESC
LIMIT 20;

-- Reset counters to start fresh measurement
TRUNCATE TABLE performance_schema.events_statements_summary_by_digest;
    

8. Praxisworkflow: enable → collect → analyze → fix → verify

Der folgende Workflow hat sich in der Praxis als effektiv erwiesen. Er ist systematisch, messbar und skaliert sowohl für kleine Projekte als auch für große E-Commerce-Systeme wie Magento.

Schritt 1: Aktivieren und 24h unter Produktionslast sammeln

-- Step 1: Enable slow query log for production collection
SET GLOBAL slow_query_log    = 'ON';
SET GLOBAL long_query_time   = 1;
SET GLOBAL log_slow_extra    = ON;  -- MySQL 8 only

-- Run for at least 24 hours covering all traffic patterns
-- (night batch jobs, business hours peak, cache-warm-up cycles)
    

Schritt 2: Top 5 Abfragemuster mit pt-query-digest identifizieren

-- Step 2: Generate digest report and identify top offenders
pt-query-digest --limit 5 /var/log/mysql/slow.log > /tmp/top5_report.txt
cat /tmp/top5_report.txt

# Quick alternative with mysqldumpslow
mysqldumpslow -s t -t 5 /var/log/mysql/slow.log
    

Schritt 3: EXPLAIN und EXPLAIN ANALYZE auf jede Abfrage

-- Step 3: Run EXPLAIN to understand the query execution plan
EXPLAIN
SELECT p.entity_id, p.sku, SUM(oi.qty_ordered) AS total_sold
FROM catalog_product_entity p
JOIN sales_order_item oi ON oi.product_id = p.entity_id
WHERE p.status = 1 AND oi.created_at >= '2024-01-01'
GROUP BY p.entity_id
ORDER BY total_sold DESC
LIMIT 25;

-- MySQL 8: EXPLAIN ANALYZE shows actual vs. estimated row counts
EXPLAIN ANALYZE
SELECT p.entity_id, p.sku, SUM(oi.qty_ordered) AS total_sold
FROM catalog_product_entity p
JOIN sales_order_item oi ON oi.product_id = p.entity_id
WHERE p.status = 1 AND oi.created_at >= '2024-01-01'
GROUP BY p.entity_id
ORDER BY total_sold DESC
LIMIT 25;
    

Schritt 4: Index ergänzen und Verbesserung messen

-- Step 4: Add the identified missing index
ALTER TABLE sales_order_item
    ADD INDEX idx_product_created (product_id, created_at);

-- Step 5: Verify improvement
-- Reset performance schema counters for clean comparison
TRUNCATE TABLE performance_schema.events_statements_summary_by_digest;

-- Re-run the query and check:
-- - Query_time should drop significantly in the next slow log entries
-- - EXPLAIN should show type=ref instead of type=ALL
-- - Rows_examined should now be close to Rows_sent

-- After verification: disable slow log if not needed permanently
-- SET GLOBAL slow_query_log = 'OFF';
    

9. Zusammenfassung

Das Slow Query Log ist das effektivste eingebaute Mittel zur Identifikation von Performance-Problemen in MySQL. Die Kombination aus log_slow_extra=ON für vollständige Metriken, mysqldumpslow für schnelle Übersichten und pt-query-digest für tiefe statistische Analysen ergibt einen professionellen, reproduzierbaren Workflow. Das Verhältnis von Rows_examined zu Rows_sent ist der schnellste Indikator für fehlende Indizes — ein Wert über 1.000:1 sollte immer untersucht werden.

10. FAQ: Slow Query Log auswerten