slow_query_log lezen op shared hosting: vier patronen

Dinsdagmiddag, een site die je vorige maand hebt overgenomen van een andere freelancer, en de CPU-grafiek van de host piekt elke negentig seconden. Je klikt wat rond in cPanel, vindt phpMyAdmin, en de homepage doet vier seconden tot first byte. Je zou er graag een profiler aan hangen, maar je hebt geen shell-toegang. Wat je wel hebt is slow_query_log (de hostingmaatschappij heeft het aan laten staan, of je hebt het zelf aangezet) en 12.000 regels van de laatste 24 uur in /home/oldsite/logs/.

De meeste regels zien er hetzelfde uit. Dat is het goede nieuws. Op een legacy site verklaren vier querypatronen ongeveer 80% van wat slow_query_log laat zien. De andere 20% is echt interessant werk; de vier hieronder zijn meestal een kwartiertje werk zodra je ze kunt lezen.

Waar het logbestand staat als je geen root hebt

Op shared hosting staat de slow query log bijna nooit in /var/log/mysql/. Hosters leiden het per account om, omdat ze niet willen dat je queries van andere klanten ziet. De twee locaties die je echt tegenkomt:

# cPanel / DirectAdmin / Plesk
/home/<account>/logs/slow_query.log
~/tmp/slow_query.log

# Managed WP-hosting (vaak uitgeschakeld, soms read-only)
/var/log/mysql-slow.log

Is het bestand leeg, kijk dan naar long_query_time. Op shared hosting staat die standaard meestal op 2.0 seconden, en een query die MySQL 400 keer per minuut bestookt op 1,2 seconden per stuk komt zo nooit in beeld. Kun je SQL uitvoeren, zet de drempel dan tijdelijk lager:

SET GLOBAL long_query_time = 0.5;
SET GLOBAL slow_query_log = 'ON';

De meeste shared hosts weigeren SET GLOBAL van een onbevoorrechte gebruiker. Zo ja, open een ticket en vraag of ze het voor jouw account willen instellen. Dit is een standaardverzoek en ze hebben er een runbook voor. De MySQL reference manual beschrijft de variabelen volledig als support tegenspartelt.

Zodra er data binnenkomt, lees het log eerst rauw door voordat je mysqldumpslow of pt-query-digest erbij pakt. Je wilt eerst de vorm van de ruis voelen.

Patroon 1: autoload die de database opvrat

De allergrootste klassieker op een WordPress-site die langer dan drie jaar draait:

SELECT option_name, option_value FROM wp_options WHERE autoload = 'yes';

Dit draait bij elke request. Het zou een paar honderd kilobyte moeten teruggeven. Op de site uit het voorbeeld was het 47 MB.

De oorzaak is bijna altijd een plugin die naar wp_options schrijft met autoload = 'yes' voor dingen die niet zouden moeten autoladen: transients die hun expiry zijn vergeten, grote arrays met gecachte API-responses, de zevendaagse rolling stats van een analyticsplugin. De query zelf is prima. De data is wat kapot is.

EXPLAIN ziet er gezond uit:

+----+-------------+------------+------+----------+------+
| id | select_type | table      | type | key      | rows |
+----+-------------+------------+------+----------+------+
|  1 | SIMPLE      | wp_options | ref  | autoload | 1432 |
+----+-------------+------------+------+----------+------+

De index wordt gebruikt. Het probleem is het aantal bytes dat teruggegeven wordt. Spoor de boosdoeners op:

SELECT option_name, LENGTH(option_value) AS bytes
FROM wp_options
WHERE autoload = 'yes'
ORDER BY bytes DESC
LIMIT 20;

Alles boven de 100 KB is verdacht. Alles boven de 1 MB is bijna altijd fout. Achterhaal per regel de plugin en zet vervolgens autoload uit of verwijder de rij:

UPDATE wp_options SET autoload = 'no' WHERE option_name = 'gravityform_cache_meta';

Maak eerst een back-up. wp_options is de WordPress-tabel die je het makkelijkst sloopt. De wp_load_alloptions-referentie is het lezen waard als je wilt begrijpen hoe WordPress het resultaat bij elke request inleest.

Patroon 2: ORDER BY post_date zonder dekkende index

Het op één na meest voorkomende patroon, van dezelfde site:

SELECT SQL_CALC_FOUND_ROWS wp_posts.ID
FROM wp_posts
WHERE wp_posts.post_type = 'product'
  AND wp_posts.post_status = 'publish'
ORDER BY wp_posts.post_date DESC
LIMIT 0, 12;

WooCommerce-shoppagina, standaard gesorteerd op datum. 0,9 seconde per aanroep. Er zijn 84.000 producten. De standaard WordPress-index op wp_posts dekt (post_type, post_status, post_date, ID) en heet type_status_date. Ontbreekt die (een vorige ontwikkelaar heeft hem gedropt, of de tabel is opgebouwd uit een gedeeltelijke dump), dan valt MySQL terug op een filesort:

Extra: Using where; Using filesort

Dat woord, "filesort", is je signaal. Het betekent dat MySQL de resultaten na het inlezen sorteert, wat op een grote tabel traag is. Zet de index terug:

ALTER TABLE wp_posts
ADD INDEX type_status_date (post_type, post_status, post_date, ID);

Doe dit in een rustig uur. Op InnoDB met MySQL 5.7 of nieuwer is dit een online operatie, maar het vreet alsnog IO en zet aan het begin en eind kort een lock op.

Nu je er toch bent: sloop SQL_CALC_FOUND_ROWS als de aanroepende code dat toelaat. WordPress core gebruikt het voor paginatie-tellingen, maar het dwingt MySQL de volledige resultset te materialiseren, wat de kosten ongeveer verdubbelt. Een aparte SELECT COUNT(*) is sneller op elke tabel boven een paar duizend rijen.

Patroon 3: LIKE '%term%' op post_content

SELECT * FROM wp_posts
WHERE post_status = 'publish'
  AND (post_title LIKE '%boiler%' OR post_content LIKE '%boiler%');

Zoekvak. Twee seconden. Elke keer.

Een LIKE met een wildcard aan het begin kan geen B-tree-index gebruiken. Het scant altijd. Op een site met 40.000 posts en een gemiddelde post_content van 8 KB lees je per zoekopdracht zo'n 300 MB aan data. De oplossing is geen index. De oplossing is stoppen met zoeken via LIKE.

Drie opties, oplopend in moeite:

1. Installeer Relevanssi of SearchWP. Die bouwen hun eigen indextabel. Vijf minuten, werkt.
2. MySQL FULLTEXT-index. Native, geen plugin. Werkt prima voor Latijnse scripts; minder goed voor CJK zonder tokenizer. ALTER TABLE wp_posts ADD FULLTEXT(post_title, post_content); en herschrijf de query naar MATCH() AGAINST().
3. Externe zoekoplossing (Algolia, Meilisearch, Typesense). Voor de meeste legacy sites overkill.

Kun je de zoekfunctie helemaal niet aanpassen, beperk dan op zijn minst de scope:

AND post_type IN ('post', 'page', 'product')
AND post_date > '2022-01-01'

Kleinere scan, dezelfde UX voor 95% van de queries.

Patroon 4: de pluginloop die N+1 wordt

Deze ziet er niet uit als een trage query. Het lijken 600 identieke snelle queries.

SELECT meta_value FROM wp_postmeta WHERE post_id = 12847 AND meta_key = '_stock_status';
SELECT meta_value FROM wp_postmeta WHERE post_id = 12848 AND meta_key = '_stock_status';
SELECT meta_value FROM wp_postmeta WHERE post_id = 12849 AND meta_key = '_stock_status';
... 597 more

Elke query kost 3 ms. Totaal: 1,8 seconde per pagina. Geen enkele overschrijdt long_query_time = 0.5, dus ze duiken nooit op in de slow log. Je vindt ze door long_query_time = 0 te zetten voor één minuut en mee te kijken, of door Query Monitor aan te zetten voor één ingelogde admin-sessie.

De oorzaak heeft altijd dezelfde vorm: een loop over posts die per rij get_post_meta() aanroept, zonder dat update_meta_cache() de cache vult en zonder 'update_post_meta_cache' => true op de bovenliggende get_posts(). Een WooCommerce-shortcode die producten op voorraadstatus lijst. Een custom widget die laatst-bijgewerkt-datums ophaalt. Een themafooter die reacties per categorie telt.

Fix het in de applicatielaag:

$ids = wp_list_pluck( $products, 'ID' );
update_meta_cache( 'post', $ids ); // één query, vult de cache
foreach ( $products as $product ) {
    $stock = get_post_meta( $product->ID, '_stock_status', true );
    // ...
}

Eén query in plaats van 600. De slow log valt vanzelf stil zodra de buffer pool niet meer aan het thrashen is.

De volgorde waarin je triage doet

Open de log, groepeer identieke queries op fingerprint, en stel per cluster de vraag: hoeveel wandkloktijd per uur kost dit? Patroon 1 beantwoordt zichzelf meestal binnen dertig seconden in wp_options. Patroon 2 is één ALTER TABLE. Patroon 3 is een plugin-installatie. Patroon 4 vereist een ontwikkelaar, maar je kunt het in- of uitsluiten door Query Monitor op een staging-kopie aan te zetten en de homepage te herladen.

Fix je autoload eerst, dan worden vrijwel alle andere patronen als bijwerking iets sneller. Minder druk op de InnoDB buffer pool betekent dat meer van wp_posts in het geheugen blijft, wat weer betekent dat filesorts en full scans minder fysieke IO doen.

Wat je vandaag nog kunt doen

Trek de slow_query_log van gisteren naar je laptop, sorteer de top 20 queries op totale wandkloktijd, en kijk of het eerste cluster overeenkomt met Patroon 1. Zo ja, dan heb je een fix die je binnen een uur kunt uitrollen, en die één UPDATE verwijderd is van een snellere homepage. Toen we Pier bouwden kwamen we dit op vrijwel elke andere site tegen waar we op dockten. Hoe we het uiteindelijk hebben opgelost: een slow-query-view die het log koppelt aan tabelgroottes en de MySQL editor in één paneel, met versiegeschiedenis op elke UPDATE zodat een verkeerde autoload-toggle terugdraaien één toetsaanslag is.