095 —PHP
php-fpm slowlog lezen: drie stack-trace patronen herkennen
Veldgids voor php-fpm slowlogs op shared hosting: de drie stack-trace vormen die je tegenkomt, wat ze betekenen en waar je het volgende uur moet zoeken.
Het is dinsdag 14:02 en de CPU-grafiek van de shared host hangt al veertig minuten op 90%. Het bureau dat de site beheert komt niet bij de server, alleen bij cPanel. Daar, onder Errors of soms verstopt achter een knop Terminal, staat een bestand php-fpm-slow.log. Ze openen het, zien een muur van tijdstempels, PIDs en ingesprongen functienamen, en sturen het door naar jou.
Deze post gaat over dat bestand. Specifiek: de drie vormen van stack trace die in een php-fpm slowlog opduiken, en wat elke vorm in stilte vertelt over waar de tijd heen gaat. Je hebt hier geen root voor nodig, geen profiler installeren. Wie de slowlog kan lezen, krijgt een trage legacy site meestal binnen tien minuten teruggebracht tot een van drie oorzaken.
Wat een slowlog-entry eigenlijk is
Een php-fpm slowlog is geen error log. Het is een sampler. Zodra een request langer duurt dan request_slowlog_timeout (vaak 5s of 10s op managed hosting), stuurt php-fpm iets in de trant van SIGUSR2 naar de worker, loopt de huidige PHP-callstack af en schrijft die snapshot naar het bestand. De request loopt gewoon door. Je ziet één bevroren moment binnen een lange request, geen volledig profiel.
Een enkele entry ziet er ongeveer zo uit:
[10-Jun-2026 13:47:12] [pool www] pid 24819
script_filename = /home/site/public_html/index.php
[0x00007f2c1c0a8b40] mysqli_query() /home/site/public_html/wp-includes/wp-db.php:2056
[0x00007f2c1c0a8a90] query() /home/site/public_html/wp-includes/wp-db.php:1830
[0x00007f2c1c0a89e0] get_results() /home/site/public_html/wp-includes/class-wp-query.php:3145
[0x00007f2c1c0a8930] get_posts() /home/site/public_html/wp-content/plugins/related-posts/related.php:88
[0x00007f2c1c0a8880] rp_render() /home/site/public_html/wp-includes/class-wp-hook.php:308
[0x00007f2c1c0a87d0] apply_filters() /home/site/public_html/wp-includes/post-template.php:256
[0x00007f2c1c0a8720] the_content() /home/site/public_html/wp-content/themes/twentytwentyone/single.php:24
Lees van boven naar beneden. Het bovenste frame is wat PHP op het moment van de sample aan het doen was. Het onderste frame is het instappunt. Alles ertussenin is de weg van het een naar het ander. Die stapel frames heeft een vorm, en die vorm is de diagnose.
Vorm één: de database-staart
De eerste en meest voorkomende vorm eindigt bovenaan in iets dat met MySQL praat: mysqli_query, PDOStatement::execute, mysql_query in echt oude code, mysqli_real_query, of soms mysqli_stmt::fetch. Daaronder zie je een of twee wrapper-functies (in WordPress: wpdb::query, get_results, get_posts), dan theme- of plugincode, en uiteindelijk het instappunt.
Als het bovenste frame een database call is en de wrappers eronder dun zijn, dan is de trage query het hele verhaal. De PHP-code is in orde. Hij heeft MySQL iets gevraagd en MySQL deed er acht seconden over.
Wat je hiermee doet: niet de PHP optimaliseren. Pak de aanwijzingen uit de stack (de pluginnaam, de functie waarin het zit) en zoek de SQL erbij. In WordPress is wpdb's last_query property je vriend als je het kunt reproduceren. Lukt dat niet, zet dan een uur lang MySQL's slow query log aan met long_query_time = 2. Leg de tijdstempels naast die van de slowlog en je hebt de SQL binnen minuten te pakken.
De fix is bijna nooit "voeg een cache toe". Meestal is het een ontbrekende index op wp_postmeta(meta_key, meta_value(10)), een ORDER BY rand() verstopt in een gerelateerde-posts-plugin, of een NOT IN subquery die door een tax-filter wordt gegenereerd en elke post scant. Je bevestigt het met EXPLAIN:
EXPLAIN SELECT p.* FROM wp_posts p
INNER JOIN wp_postmeta m ON m.post_id = p.ID
WHERE m.meta_key = '_related_tags'
AND m.meta_value LIKE '%shoes%'
ORDER BY p.post_date DESC
LIMIT 5;
Staat er in de kolom type de waarde ALL en lopen de rijaantallen in de miljoenen, dan heb je 'm gevonden.
Vorm twee: de hook-lawine
De tweede vorm herken je na de tweede keer dat je hem ziet. Het bovenste frame is iets goedkoops en onschuldigs. preg_match. strtolower. apply_filters zelf. WP_Hook::apply_filters. Daaronder: weer een apply_filters. Daaronder: nog een apply_filters. De stack is twintig, dertig, vijftig frames diep en het zijn grotendeels dezelfde drie functienamen die zich herhalen.
[0x...] strtolower() /home/site/.../seo-plugin/canonical.php:412
[0x...] WP_Hook::apply_filters() /home/site/.../class-wp-hook.php:308
[0x...] apply_filters() /home/site/.../wp-includes/link-template.php:127
[0x...] get_permalink() /home/site/.../seo-plugin/sitemap.php:88
[0x...] WP_Hook::apply_filters() /home/site/.../class-wp-hook.php:308
[0x...] apply_filters() /home/site/.../wp-includes/post-template.php:256
... (continues for 40+ frames)
Dit is geen trage functie. Dit is een op hol geslagen lus van goedkope functies, bijna altijd veroorzaakt door een plugin die op the_content of get_permalink haakt en dan, binnen z'n eigen filter, voor elke post in het archief opnieuw get_permalink aanroept. Vermenigvuldig met 200 posts per pagina plus een paar geneste hooks en je hebt een request die veertig miljoen functie-aanroepen doet om één categoriepagina te renderen.
Wat je hiermee doet: vis de plugin uit de directorynaam middenin de stack en zet hem op een staging-kopie uit. Zakt de load, dan heb je hem te pakken. De echte fix is meestal één regel guard bovenin de filter-callback om werk over te slaan dat niet nodig is.
Vorm drie: de remote call
De derde vorm wordt het vaakst verkeerd gediagnosticeerd. Bovenaan de stack staat stream_socket_client, fsockopen, curl_exec, of fread op een stream-resource. Daaronder wp_remote_get, WP_Http::request, of een meegeleverde Guzzle-handler. Daar weer onder de applicatiecode.
[0x...] curl_exec() /home/site/.../wp-includes/class-wp-http-curl.php:226
[0x...] WP_Http_Curl::request() /home/site/.../class-wp-http.php:430
[0x...] WP_Http::request() /home/site/.../http.php:191
[0x...] wp_remote_get() /home/site/.../plugins/social-feed/feed.php:54
[0x...] sf_render_widget() /home/site/.../class-wp-widget.php:394
De PHP is niet traag. MySQL is niet traag. De site staat te wachten op de server van iemand anders. Een social-feed plugin die Instagram pollt, een valutaomrekener die een FX-endpoint aanroept, een licentiechecker die naar huis belt, een oude Gravatar-lookup zonder timeout. De request duurt acht seconden omdat de upstream er acht seconden over deed, of erger: tegen PHP's standaard default_socket_timeout van 60 seconden aanloopt en daar dicht bij komt.
De diagnose is hier de makkelijkste van de drie: de URL staat meestal gewoon in het pluginbestand dat in het onderste applicatieframe genoemd wordt. Open het, zoek de wp_remote_get aanroep, kijk welke host hij aanspreekt. Test die host vanaf je laptop met curl -w "%{time_total}\n" -o /dev/null -s <url>. Is het bij jou ook traag, dan is de fix een transient cache (de plugin hoort de response 15 minuten in wp_options te bewaren, niet de API plat te leggen bij elke pageload) plus een agressieve timeout-parameter:
$response = wp_remote_get( $url, [
'timeout' => 3,
'redirection' => 1,
'user-agent' => 'site-name/1.0',
] );
if ( is_wp_error( $response ) ) {
return $cached_fallback;
}
Drie seconden is een redelijk plafond voor een synchrone third-party call binnen een page render. Alles daarboven en de upstream bezit je uptime.
Wat de slowlog je niet vertelt
Twee eerlijke beperkingen, even hardop. Eén: de slowlog is een snapshot, geen tijdlijn. Duurt een request 9 seconden en krijg je één sample, dan zie je wat er op één moment op de stack stond. Een tweede sample van dezelfde request kan op een andere vorm uitkomen. Wanneer twee opeenvolgende entries in dezelfde PID verschillende vormen tonen, zijn ze allebei echt en moeten ze allebei opgelost worden.
Twee: de slowlog ziet geen opcode-cache misses, geen session_start die op een file lock blokkeert, geen APCu-contentie. Die presenteren zich meestal als vorm één zonder database call bovenaan, of als vorm twee met een verdacht laag frame-aantal. Passen de vormen niet op wat je ziet, kijk dan naar request_terminate_timeout en naar de vraag of de hosting onder load draait op één file-based session-backend.
Iets kleins voor vandaag
Heb je toegang tot een verouderde site die om onverklaarbare redenen traag is, vraag de hostingmaatschappij dan om request_slowlog_timeout = 5s aan te zetten en naar een bestand te schrijven dat jij kunt lezen. Laat het een dag staan. De vormen sorteren zichzelf en je komt terug bij een bestand dat, aandachtig gelezen, het grootste deel van de diagnose al voor je gedaan heeft.
Toen we Pier bouwden liepen we steeds tegen dezelfde shared-host situatie aan: klanten met de slowlog zichtbaar in cPanel, maar niets om hem mee te lezen. De manier waarop we dat uiteindelijk hebben opgelost was door de MySQL editor en de bestandsbrowser in dezelfde chatsessie te zetten, zodat je een stackframe kunt plakken en kunt vragen "welke query draait deze plugin op de homepage" zonder de app uit te hoeven. Het is het soort kleinigheid dat zichzelf terugverdient zodra een site om 02:00 's nachts plat ligt.
— Vragen —
Waar vind ik de php-fpm slowlog op een shared host?
Meestal onder het Metrics- of Errors-paneel van cPanel, of op een pad zoals /home/USER/logs/php-fpm-slow.log. Zie je hem niet, vraag de hosting dan om request_slowlog_timeout aan te zetten en hem naar een leesbaar bestand te laten schrijven.
Wat is een verstandige waarde voor request_slowlog_timeout?
5 seconden op een gezonde site, 2 seconden als je actief aan het jagen bent. Onder de 2s loopt het bestand vol met normaal verkeer en wordt het onbruikbaar.
Vangt de slowlog ook fatal errors of 500's?
Nee. Hij sampelt alleen requests die voorbij de timeout nog draaien. Voor fatals moet je in php's error_log kijken; voor 500's de access log van de webserver gecombineerd met de error_log.