MySQL Slow Query Log: dure queries opsporen

Wanneer je gameserver of webapplicatie begint te haperen, is de boosdoener meestal een handvol dure SQL-queries, en die met het blote oog vinden is onmogelijk. Precies hier bewijst het MySQL slow query log zijn waarde: het legt stilletjes elke query vast die langer duurt dan een drempel die jij instelt, zodat je naar data kijkt in plaats van te gokken. In dit artikel loop ik stap voor stap door het correct inschakelen van het log, het kiezen van de juiste instellingen en het systematisch eruit halen van je duurste queries.

Wat het slow query log precies is

Het slow query log is een MySQL-functie die elke SQL-instructie vastlegt die langer loopt dan long_query_time seconden. "Traag" is relatief: een character-lookup van 0,5 seconde op een Metin2-server is een ramp, terwijl 2 seconden op een rapportagescherm prima kan zijn. Elke regel bewaart de querytijd, de locktijd, het aantal onderzochte rijen en het aantal verzonden rijen. De echte kracht zit in die metadata: heel vaak is het probleem niet de query zelf, maar dat hij miljoenen rijen scant om er tien terug te geven.

Het log inschakelen: persistente configuratie

De meest robuuste aanpak is schrijven naar my.cnf (op Debian/Ubuntu meestal /etc/mysql/mysql.conf.d/mysqld.cnf). Voeg dit toe onder het blok [mysqld]:

[mysqld]
slow_query_log = 1
slow_query_log_file = /var/log/mysql/slow.log
long_query_time = 1
log_queries_not_using_indexes = 1
min_examined_row_limit = 100

Herstart daarna de service: sudo systemctl restart mysql. Dit doet elke optie:

• long_query_time — de drempel in seconden. Hij accepteert decimalen, dus je kunt 0.5 schrijven.
• log_queries_not_using_indexes — logt elke query die geen index gebruikt, zelfs snelle. Onbetaalbaar tijdens ontwikkeling, maar het kan veel ruis opleveren.
• min_examined_row_limit — negeert queries die minder dan dit aantal rijen onderzoeken, zodat kleine tabellen het log niet opblazen.

Live inschakelen, zonder herstart

Kun je een productieserver niet herstarten, dan laat MySQL je de meeste van deze variabelen tijdens runtime wijzigen. Maak verbinding als root en voer uit:

SET GLOBAL slow_query_log = 'ON';
SET GLOBAL long_query_time = 1;
SET GLOBAL log_queries_not_using_indexes = 'ON';

Eén kanttekening: long_query_time wordt per sessie gelezen, dus alleen nieuwe verbindingen nemen de waarde over; je bestaande connection pool blijft de oude drempel gebruiken. Bovendien gaan wijzigingen via SET GLOBAL verloren bij een herstart — voor persistentie heb je nog steeds my.cnf nodig.

De duurste queries eruit halen: pt-query-digest

Het ruwe log met de hand lezen is een kwelling; dezelfde query herhaalt zich honderden keren. Het hulpprogramma pt-query-digest uit Percona Toolkit normaliseert die regels (het vervangt letterlijke waarden door ?) en groepeert identieke queries onder één "fingerprint". Installatie op Debian/Ubuntu:

sudo apt install percona-toolkit
pt-query-digest /var/log/mysql/slow.log > rapport.txt

Het rapport rangschikt queries bovenaan op totaal bestede tijd — een query van 50 ms die 200 keer per seconde loopt telt net zo zwaar als een query die één keer 5 seconden duurt. Per groep krijg je het aantal aanroepen, de totale en gemiddelde tijd, en een voorbeeldquery. Meestal zijn de top drie queries verantwoordelijk voor het grootste deel van de belasting; focus daarop in plaats van blind te optimaliseren.

Een query lezen: EXPLAIN en indexen

Heb je de boosdoener gevonden, zet er dan EXPLAIN voor om het plan van MySQL te zien:

EXPLAIN SELECT * FROM player WHERE account_id = 4210 ORDER BY level DESC;

De velden om op te letten in de uitvoer:

• type — zie je ALL, dan is het een volledige tabelscan, wat slecht is; je wilt ref of range.
• key — als deze NULL is, wordt er helemaal geen index gebruikt.
• rows — het geschatte aantal rijen dat MySQL van plan is te scannen; is dat veel groter dan je resultaat, dan zit het probleem hier.
• Extra — Using filesort of Using temporary betekent extra kosten voor sorteren of groeperen.

In het voorbeeld hierboven laat een index op account_id de scan instorten: CREATE INDEX idx_player_account ON player (account_id);. Voor kolommen die vaak samen worden gefilterd, overweeg een samengestelde (composite) index — maar elke onnodige index kost extra bij het schrijven, dus meet voordat je toevoegt.

Het log onder controle houden

Het slow query log groeit na verloop van tijd; in productie moet je het roteren. De meeste distributies leveren /etc/logrotate.d/mysql-server, en zo niet, dan volstaat een eenvoudige regel. Is de diagnose klaar, schakel dan log_queries_not_using_indexes uit; deze optie kan het bestand vullen met kleine maar index-loze queries. Op drukke servers waar disk-I/O kostbaar is, schakel je het log alleen in tijdens onderzoek en houd je long_query_time de rest van de tijd op een verstandige drempel (zoals 1).

Veelgestelde vragen

Vertraagt het slow query log de prestaties?

Met een redelijke drempel is de impact verwaarloosbaar, omdat alleen queries die die drempel overschrijden worden weggeschreven. De echte kosten komen met log_queries_not_using_indexes ingeschakeld: op een server met veel verkeer kan dat het logbestand en de schijfschrijfacties snel opblazen. Houd het uit buiten de diagnose.

Op welke waarde moet ik long_query_time zetten?

Begin met 1 seconde. Wordt er niets gevangen, verlaag dan geleidelijk (0.5, dan 0.2). Een te lage waarde vult het log met ruis; het doel is de duurste queries te zien, niet elke query.

Kan ik naar een tabel loggen in plaats van een bestand?

Ja, met log_output = 'TABLE' gaan de records naar de tabel mysql.slow_log en kun je ze met SQL bevragen. Maar bestandsuitvoer is veel praktischer met pt-query-digest, dus een bestand verdient in de meeste gevallen de voorkeur.

Vertraagt je server en weet je niet waar te beginnen, dan kunnen we samen het slow query log inschakelen en je eerste pt-query-digest-rapport interpreteren. Voor een MySQL-prestatieaudit en query-optimalisatie, neem contact met me op.